2021-09-02T18:19:29.320Z,1630606769.320 [CommandExec](IMPORTANT): got command restart logs 2021-09-02T18:23:44.512Z,1630607024.512 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:23:44.512Z,1630607024.512 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:23:44.512Z,1630607024.512 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:23:44.513Z,1630607024.513 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:23:44.917Z,1630607024.917 [Default:CheckIn:D] Stopped 2021-09-02T18:23:44.917Z,1630607024.917 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:23:45.330Z,1630607025.330 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.635665 min 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn:E] Stopped 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn] Stopped 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn](INFO): Running loop #12 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn] Running Loop=12 2021-09-02T18:23:45.331Z,1630607025.331 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:23:45.332Z,1630607025.332 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:23:47.328Z,1630607027.328 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182346.00,A,3648.37562,N,12147.40875,W,14.676,40.95,020921,,,D*72 2021-09-02T18:23:47.331Z,1630607027.331 [NAL9602](INFO): GPS fix at 20210902T182346: (36.806260, -121.790146) 2021-09-02T18:23:47.342Z,1630607027.342 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:23:47.342Z,1630607027.342 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:23:55.080Z,1630607035.080 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210902T140929/Courier0072.lzma 2021-09-02T18:23:56.083Z,1630607036.083 [DataOverHttps](INFO): Moved sent file to Logs/20210902T140929/Courier0072.lzma.bak 2021-09-02T18:23:56.083Z,1630607036.083 [DataOverHttps](INFO): SBD MOMSN=15908362 2021-09-02T18:24:12.377Z,1630607052.377 [DataOverHttps](INFO): Sending 269 bytes from file Logs/20210902T181929/Courier0000.lzma 2021-09-02T18:24:13.379Z,1630607053.379 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0000.lzma.bak 2021-09-02T18:24:13.379Z,1630607053.379 [DataOverHttps](INFO): SBD MOMSN=15908364 2021-09-02T18:24:17.224Z,1630607057.224 [NAL9602](INFO): SBD MO Status=0, MOMSN=29676, MT Status=0, MTMSN=0 2021-09-02T18:24:17.224Z,1630607057.224 [NAL9602](INFO): No messages in MT queue 2021-09-02T18:24:29.368Z,1630607069.368 [DataOverHttps](INFO): Sending 106 bytes from file Logs/20210902T140929/Express0073.lzma 2021-09-02T18:24:30.371Z,1630607070.371 [DataOverHttps](INFO): Moved sent file to Logs/20210902T140929/Express0073.lzma.bak 2021-09-02T18:24:30.371Z,1630607070.371 [DataOverHttps](INFO): SBD MOMSN=15908368 2021-09-02T18:24:46.365Z,1630607086.365 [DataOverHttps](INFO): Sending 400 bytes from file Logs/20210902T181929/Express0001.lzma 2021-09-02T18:24:47.367Z,1630607087.367 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0001.lzma.bak 2021-09-02T18:24:47.367Z,1630607087.367 [DataOverHttps](INFO): SBD MOMSN=15908372 2021-09-02T18:24:47.926Z,1630607087.926 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T18:25:06.564Z,1630607106.564 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20210902T181929/Express0004.lzma 2021-09-02T18:25:07.567Z,1630607107.567 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0004.lzma.bak 2021-09-02T18:25:07.567Z,1630607107.567 [DataOverHttps](INFO): SBD MOMSN=15908376 2021-09-02T18:25:09.034Z,1630607109.034 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:25:09.034Z,1630607109.034 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:25:09.034Z,1630607109.034 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:29:08.254Z,1630607348.254 [CBIT](IMPORTANT): Beginning ground fault scan 2021-09-02T18:29:19.167Z,1630607359.167 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.002118 CHAN A1 (24V): 0.000659 CHAN A2 (12V): -0.002345 CHAN A3 (5V): -0.001607 CHAN B0 (3.3V): -0.000290 CHAN B1 (3.15aV): -0.000070 CHAN B2 (3.15bV): -0.000017 CHAN B3 (GND): 0.000323 OPEN: -0.000495 Full Scale Calc: 4.765 mA, -1.589 mA 2021-09-02T18:30:09.651Z,1630607409.651 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:30:09.651Z,1630607409.651 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:30:09.651Z,1630607409.651 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:30:09.651Z,1630607409.651 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:30:10.040Z,1630607410.040 [Default:CheckIn:D] Stopped 2021-09-02T18:30:10.040Z,1630607410.040 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:30:10.445Z,1630607410.445 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.054386 min 2021-09-02T18:30:10.445Z,1630607410.445 [Default:CheckIn:E] Stopped 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn] Stopped 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn](INFO): Running loop #13 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn] Running Loop=13 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:30:10.446Z,1630607410.446 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:30:12.456Z,1630607412.456 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183011.00,A,3648.26161,N,12147.13759,W,4.315,184.96,020921,,,A*7C 2021-09-02T18:30:12.458Z,1630607412.458 [NAL9602](INFO): GPS fix at 20210902T183011: (36.804360, -121.785627) 2021-09-02T18:30:12.498Z,1630607412.498 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:30:12.498Z,1630607412.498 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:30:20.332Z,1630607420.332 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0006.lzma 2021-09-02T18:30:21.334Z,1630607421.334 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0006.lzma.bak 2021-09-02T18:30:21.335Z,1630607421.335 [DataOverHttps](INFO): SBD MOMSN=15908378 2021-09-02T18:30:37.382Z,1630607437.382 [DataOverHttps](INFO): Sending 351 bytes from file Logs/20210902T181929/Express0007.lzma 2021-09-02T18:30:38.383Z,1630607438.383 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0007.lzma.bak 2021-09-02T18:30:38.383Z,1630607438.383 [DataOverHttps](INFO): SBD MOMSN=15908381 2021-09-02T18:30:39.551Z,1630607439.551 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:30:39.551Z,1630607439.551 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:30:39.551Z,1630607439.551 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:31:14.672Z,1630607474.672 [NAL9602](INFO): SBD MO Status=2, MOMSN=29677, MT Status=2, MTMSN=0 2021-09-02T18:31:14.672Z,1630607474.672 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:32:16.495Z,1630607536.495 [NAL9602](INFO): SBD MO Status=2, MOMSN=29677, MT Status=2, MTMSN=0 2021-09-02T18:32:16.496Z,1630607536.496 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:32:36.284Z,1630607556.284 [NAL9602](INFO): SBD MO Status=2, MOMSN=29677, MT Status=2, MTMSN=0 2021-09-02T18:32:36.284Z,1630607556.284 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:32:55.289Z,1630607575.289 [NAL9602](INFO): SBD MO Status=0, MOMSN=29677, MT Status=0, MTMSN=0 2021-09-02T18:32:55.289Z,1630607575.289 [NAL9602](INFO): No messages in MT queue 2021-09-02T18:33:25.978Z,1630607605.978 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T18:35:40.176Z,1630607740.176 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:35:40.177Z,1630607740.177 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:35:40.177Z,1630607740.177 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:35:40.177Z,1630607740.177 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:35:40.586Z,1630607740.586 [Default:CheckIn:D] Stopped 2021-09-02T18:35:40.586Z,1630607740.586 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.563485 min 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn:E] Stopped 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn] Stopped 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:35:40.988Z,1630607740.988 [Default:CheckIn](INFO): Running loop #14 2021-09-02T18:35:40.989Z,1630607740.989 [Default:CheckIn] Running Loop=14 2021-09-02T18:35:40.989Z,1630607740.989 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:35:40.989Z,1630607740.989 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:35:42.996Z,1630607742.996 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183542.00,A,3648.15028,N,12147.22004,W,0.097,218.97,020921,,,A*74 2021-09-02T18:35:42.999Z,1630607742.999 [NAL9602](INFO): GPS fix at 20210902T183542: (36.802505, -121.787001) 2021-09-02T18:35:43.014Z,1630607743.014 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:35:43.014Z,1630607743.014 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:35:50.648Z,1630607750.648 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0009.lzma 2021-09-02T18:35:51.652Z,1630607751.652 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0009.lzma.bak 2021-09-02T18:35:51.653Z,1630607751.653 [DataOverHttps](INFO): SBD MOMSN=15908387 2021-09-02T18:36:07.781Z,1630607767.781 [DataOverHttps](INFO): Sending 146 bytes from file Logs/20210902T181929/Express0010.lzma 2021-09-02T18:36:08.782Z,1630607768.782 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0010.lzma.bak 2021-09-02T18:36:08.783Z,1630607768.783 [DataOverHttps](INFO): SBD MOMSN=15908390 2021-09-02T18:36:10.073Z,1630607770.073 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:36:10.073Z,1630607770.073 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:36:10.073Z,1630607770.073 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:36:38.748Z,1630607798.748 [NAL9602](INFO): SBD MO Status=2, MOMSN=29678, MT Status=2, MTMSN=0 2021-09-02T18:36:38.748Z,1630607798.748 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:37:02.196Z,1630607822.196 [NAL9602](INFO): SBD MO Status=0, MOMSN=29678, MT Status=0, MTMSN=0 2021-09-02T18:37:02.196Z,1630607822.196 [NAL9602](INFO): No messages in MT queue 2021-09-02T18:37:32.893Z,1630607852.893 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T18:41:10.738Z,1630608070.738 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:41:10.738Z,1630608070.738 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:41:10.738Z,1630608070.738 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:41:10.738Z,1630608070.738 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:41:11.128Z,1630608071.128 [Default:CheckIn:D] Stopped 2021-09-02T18:41:11.128Z,1630608071.128 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.072526 min 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn:E] Stopped 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn] Stopped 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn](INFO): Running loop #15 2021-09-02T18:41:11.531Z,1630608071.531 [Default:CheckIn] Running Loop=15 2021-09-02T18:41:11.532Z,1630608071.532 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:41:11.532Z,1630608071.532 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:41:13.547Z,1630608073.547 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184112.00,A,3648.15003,N,12147.22312,W,0.019,263.58,020921,,,A*76 2021-09-02T18:41:13.550Z,1630608073.550 [NAL9602](INFO): GPS fix at 20210902T184112: (36.802501, -121.787052) 2021-09-02T18:41:13.566Z,1630608073.566 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:41:13.567Z,1630608073.567 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:41:21.193Z,1630608081.193 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210902T181929/Courier0012.lzma 2021-09-02T18:41:22.195Z,1630608082.195 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0012.lzma.bak 2021-09-02T18:41:22.195Z,1630608082.195 [DataOverHttps](INFO): SBD MOMSN=15908394 2021-09-02T18:41:38.336Z,1630608098.336 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20210902T181929/Express0013.lzma 2021-09-02T18:41:39.339Z,1630608099.339 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0013.lzma.bak 2021-09-02T18:41:39.339Z,1630608099.339 [DataOverHttps](INFO): SBD MOMSN=15908397 2021-09-02T18:41:40.638Z,1630608100.638 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:41:40.638Z,1630608100.638 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:41:40.638Z,1630608100.638 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:42:01.218Z,1630608121.218 [NAL9602](INFO): SBD MO Status=2, MOMSN=29679, MT Status=2, MTMSN=0 2021-09-02T18:42:01.219Z,1630608121.219 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:42:26.664Z,1630608146.664 [NAL9602](INFO): SBD MO Status=2, MOMSN=29679, MT Status=2, MTMSN=0 2021-09-02T18:42:26.664Z,1630608146.664 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T18:42:39.996Z,1630608159.996 [NAL9602](INFO): SBD MO Status=0, MOMSN=29679, MT Status=0, MTMSN=0 2021-09-02T18:42:39.996Z,1630608159.996 [NAL9602](INFO): No messages in MT queue 2021-09-02T18:43:10.706Z,1630608190.706 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T18:46:41.240Z,1630608401.240 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:46:41.241Z,1630608401.241 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:46:41.241Z,1630608401.241 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:46:41.241Z,1630608401.241 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:46:41.652Z,1630608401.652 [Default:CheckIn:D] Stopped 2021-09-02T18:46:41.652Z,1630608401.652 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:46:42.063Z,1630608402.063 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.581258 min 2021-09-02T18:46:42.063Z,1630608402.063 [Default:CheckIn:E] Stopped 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn] Stopped 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn](INFO): Running loop #16 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn] Running Loop=16 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:46:42.064Z,1630608402.064 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:46:44.060Z,1630608404.060 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184643.00,A,3648.16961,N,12147.27657,W,0.214,313.98,020921,,,A*7F 2021-09-02T18:46:44.062Z,1630608404.062 [NAL9602](INFO): GPS fix at 20210902T184643: (36.802827, -121.787943) 2021-09-02T18:46:44.073Z,1630608404.073 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:46:44.073Z,1630608404.073 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:46:54.613Z,1630608414.613 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0015.lzma 2021-09-02T18:46:55.607Z,1630608415.607 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0015.lzma.bak 2021-09-02T18:46:55.607Z,1630608415.607 [DataOverHttps](INFO): SBD MOMSN=15908401 2021-09-02T18:47:11.976Z,1630608431.976 [DataOverHttps](INFO): Sending 142 bytes from file Logs/20210902T181929/Express0016.lzma 2021-09-02T18:47:12.979Z,1630608432.979 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0016.lzma.bak 2021-09-02T18:47:12.979Z,1630608432.979 [DataOverHttps](INFO): SBD MOMSN=15908404 2021-09-02T18:47:14.432Z,1630608434.432 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:47:14.432Z,1630608434.432 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:47:14.432Z,1630608434.432 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:51:46.419Z,1630608706.419 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T18:52:15.112Z,1630608735.112 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:52:15.112Z,1630608735.112 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:52:15.113Z,1630608735.113 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:52:15.113Z,1630608735.113 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:52:15.521Z,1630608735.521 [Default:CheckIn:D] Stopped 2021-09-02T18:52:15.521Z,1630608735.521 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.145744 min 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn:E] Stopped 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn] Stopped 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn](INFO): Running loop #17 2021-09-02T18:52:15.913Z,1630608735.913 [Default:CheckIn] Running Loop=17 2021-09-02T18:52:15.914Z,1630608735.914 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:52:15.914Z,1630608735.914 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:52:17.928Z,1630608737.928 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185217.00,A,3648.16168,N,12147.27910,W,0.836,154.24,020921,,,A*7A 2021-09-02T18:52:17.930Z,1630608737.930 [NAL9602](INFO): GPS fix at 20210902T185217: (36.802695, -121.787985) 2021-09-02T18:52:17.942Z,1630608737.942 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:52:17.942Z,1630608737.942 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:52:25.888Z,1630608745.888 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0018.lzma 2021-09-02T18:52:26.891Z,1630608746.891 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0018.lzma.bak 2021-09-02T18:52:26.891Z,1630608746.891 [DataOverHttps](INFO): SBD MOMSN=15908407 2021-09-02T18:52:42.929Z,1630608762.929 [DataOverHttps](INFO): Sending 231 bytes from file Logs/20210902T181929/Express0019.lzma 2021-09-02T18:52:43.931Z,1630608763.931 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0019.lzma.bak 2021-09-02T18:52:43.931Z,1630608763.931 [DataOverHttps](INFO): SBD MOMSN=15908410 2021-09-02T18:52:45.411Z,1630608765.411 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:52:45.411Z,1630608765.411 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:52:45.411Z,1630608765.411 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:52:50.718Z,1630608770.718 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T18:57:46.186Z,1630609066.186 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T18:57:46.186Z,1630609066.186 [Default:CheckIn:C.Wait] Stopped 2021-09-02T18:57:46.186Z,1630609066.186 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T18:57:46.187Z,1630609066.187 [Default:CheckIn:D] Running Loop=1 2021-09-02T18:57:46.605Z,1630609066.605 [Default:CheckIn:D] Stopped 2021-09-02T18:57:46.605Z,1630609066.605 [Default:CheckIn:E] Running Loop=1 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.663810 min 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn:E] Stopped 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn] Stopped 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn](INFO): Running loop #18 2021-09-02T18:57:46.975Z,1630609066.975 [Default:CheckIn] Running Loop=18 2021-09-02T18:57:46.976Z,1630609066.976 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T18:57:46.976Z,1630609066.976 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T18:57:48.986Z,1630609068.986 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185748.00,A,3648.15938,N,12147.27913,W,0.641,202.40,020921,,,A*74 2021-09-02T18:57:48.988Z,1630609068.988 [NAL9602](INFO): GPS fix at 20210902T185748: (36.802656, -121.787986) 2021-09-02T18:57:48.999Z,1630609068.999 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T18:57:48.999Z,1630609068.999 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T18:57:56.832Z,1630609076.832 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210902T181929/Courier0021.lzma 2021-09-02T18:57:57.835Z,1630609077.835 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0021.lzma.bak 2021-09-02T18:57:57.835Z,1630609077.835 [DataOverHttps](INFO): SBD MOMSN=15908415 2021-09-02T18:58:13.848Z,1630609093.848 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20210902T181929/Express0022.lzma 2021-09-02T18:58:15.029Z,1630609095.029 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0022.lzma.bak 2021-09-02T18:58:15.029Z,1630609095.029 [DataOverHttps](INFO): SBD MOMSN=15908418 2021-09-02T18:58:16.070Z,1630609096.070 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T18:58:16.070Z,1630609096.070 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T18:58:16.071Z,1630609096.071 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T18:58:19.730Z,1630609099.730 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T18:58:19.813Z,1630609099.813 [NAL9602](ERROR): received: +CSQ:0 OK679, 0, 0, 0, 0 OK 2021-09-02T19:00:05.252Z,1630609205.252 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:00:05.252Z,1630609205.252 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:00:21.460Z,1630609221.460 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:00:21.461Z,1630609221.461 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:02:51.014Z,1630609371.014 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:03:16.896Z,1630609396.896 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:03:16.896Z,1630609396.896 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:03:16.896Z,1630609396.896 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:03:16.897Z,1630609396.897 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:03:17.292Z,1630609397.292 [Default:CheckIn:D] Stopped 2021-09-02T19:03:17.292Z,1630609397.292 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.175252 min 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn:E] Stopped 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn] Stopped 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:03:17.704Z,1630609397.704 [Default:CheckIn](INFO): Running loop #19 2021-09-02T19:03:17.705Z,1630609397.705 [Default:CheckIn] Running Loop=19 2021-09-02T19:03:17.705Z,1630609397.705 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:03:17.705Z,1630609397.705 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:03:19.703Z,1630609399.703 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190318.00,A,3648.16931,N,12147.28257,W,1.419,74.16,020921,,,A*41 2021-09-02T19:03:19.706Z,1630609399.706 [NAL9602](INFO): GPS fix at 20210902T190318: (36.802822, -121.788043) 2021-09-02T19:03:19.744Z,1630609399.744 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:03:19.744Z,1630609399.744 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:03:27.605Z,1630609407.605 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0024.lzma 2021-09-02T19:03:28.607Z,1630609408.607 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0024.lzma.bak 2021-09-02T19:03:28.607Z,1630609408.607 [DataOverHttps](INFO): SBD MOMSN=15908424 2021-09-02T19:03:44.609Z,1630609424.609 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20210902T181929/Express0025.lzma 2021-09-02T19:03:45.611Z,1630609425.611 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0025.lzma.bak 2021-09-02T19:03:45.611Z,1630609425.611 [DataOverHttps](INFO): SBD MOMSN=15908427 2021-09-02T19:03:46.782Z,1630609426.782 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:03:46.782Z,1630609426.782 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:03:46.782Z,1630609426.782 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:03:52.424Z,1630609432.424 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T19:08:47.476Z,1630609727.476 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:08:47.476Z,1630609727.476 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:08:47.476Z,1630609727.476 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:08:47.481Z,1630609727.481 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:08:47.906Z,1630609727.906 [Default:CheckIn:D] Stopped 2021-09-02T19:08:47.906Z,1630609727.906 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:08:48.281Z,1630609728.281 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.685482 min 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn:E] Stopped 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn] Stopped 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn](INFO): Running loop #20 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn] Running Loop=20 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:08:48.282Z,1630609728.282 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:08:50.279Z,1630609730.279 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190849.00,A,3648.16732,N,12147.28115,W,0.350,150.59,020921,,,A*71 2021-09-02T19:08:50.289Z,1630609730.289 [NAL9602](INFO): GPS fix at 20210902T190849: (36.802789, -121.788019) 2021-09-02T19:08:50.300Z,1630609730.300 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:08:50.300Z,1630609730.300 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:09:00.464Z,1630609740.464 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0027.lzma 2021-09-02T19:09:01.467Z,1630609741.467 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0027.lzma.bak 2021-09-02T19:09:01.467Z,1630609741.467 [DataOverHttps](INFO): SBD MOMSN=15908431 2021-09-02T19:09:17.404Z,1630609757.404 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20210902T181929/Express0028.lzma 2021-09-02T19:09:18.407Z,1630609758.407 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0028.lzma.bak 2021-09-02T19:09:18.407Z,1630609758.407 [DataOverHttps](INFO): SBD MOMSN=15908434 2021-09-02T19:09:19.890Z,1630609759.890 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:09:19.890Z,1630609759.890 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:09:19.890Z,1630609759.890 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:09:21.083Z,1630609761.083 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T19:09:21.157Z,1630609761.157 [NAL9602](ERROR): received: +CSQ:0 OK680, 2, 0, 0, 0 OK 2021-09-02T19:11:02.491Z,1630609862.491 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:11:02.492Z,1630609862.492 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:12:06.853Z,1630609926.853 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:12:06.853Z,1630609926.853 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:13:52.638Z,1630610032.638 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:14:06.720Z,1630610046.720 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2021-09-02T19:14:20.494Z,1630610060.494 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:14:20.495Z,1630610060.495 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:14:20.495Z,1630610060.495 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:14:20.495Z,1630610060.495 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:14:20.939Z,1630610060.939 [Default:CheckIn:D] Stopped 2021-09-02T19:14:20.939Z,1630610060.939 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:14:21.322Z,1630610061.322 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 114.236043 min 2021-09-02T19:14:21.322Z,1630610061.322 [Default:CheckIn:E] Stopped 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn] Stopped 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn](INFO): Running loop #21 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn] Running Loop=21 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:14:21.323Z,1630610061.323 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:14:23.280Z,1630610063.280 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191422.00,A,3648.16679,N,12147.28425,W,0.311,272.82,020921,,,D*7C 2021-09-02T19:14:23.283Z,1630610063.283 [NAL9602](INFO): GPS fix at 20210902T191422: (36.802780, -121.788071) 2021-09-02T19:14:23.314Z,1630610063.314 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:14:23.314Z,1630610063.314 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:14:30.684Z,1630610070.684 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0030.lzma 2021-09-02T19:14:31.687Z,1630610071.687 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0030.lzma.bak 2021-09-02T19:14:31.687Z,1630610071.687 [DataOverHttps](INFO): SBD MOMSN=15908438 2021-09-02T19:14:48.709Z,1630610088.709 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20210902T181929/Express0031.lzma 2021-09-02T19:14:49.711Z,1630610089.711 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0031.lzma.bak 2021-09-02T19:14:49.711Z,1630610089.711 [DataOverHttps](INFO): SBD MOMSN=15908441 2021-09-02T19:14:51.206Z,1630610091.206 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:14:51.206Z,1630610091.206 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:14:51.206Z,1630610091.206 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:14:55.671Z,1630610095.671 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T19:16:46.776Z,1630610206.776 [BPC1](ERROR): BPC1A: No match for serial number 1717 in BPC1A's battery stick inventory (sticks 1-32 in onboard configuration file). 2021-09-02T19:17:42.106Z,1630610262.106 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2021-09-02T19:17:42.109Z,1630610262.109 [BPC1](INFO): Received data from all battery sticks. 2021-09-02T19:19:51.797Z,1630610391.797 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:19:51.797Z,1630610391.797 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:19:51.797Z,1630610391.797 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:19:51.797Z,1630610391.797 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:19:52.204Z,1630610392.204 [Default:CheckIn:D] Stopped 2021-09-02T19:19:52.204Z,1630610392.204 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:19:52.616Z,1630610392.616 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.757121 min 2021-09-02T19:19:52.616Z,1630610392.616 [Default:CheckIn:E] Stopped 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn] Stopped 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn](INFO): Running loop #22 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn] Running Loop=22 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:19:52.617Z,1630610392.617 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:19:54.616Z,1630610394.616 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191953.00,A,3648.16654,N,12147.28177,W,0.253,272.82,020921,,,D*7D 2021-09-02T19:19:54.618Z,1630610394.618 [NAL9602](INFO): GPS fix at 20210902T191953: (36.802776, -121.788029) 2021-09-02T19:19:54.629Z,1630610394.629 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:19:54.630Z,1630610394.630 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:20:02.365Z,1630610402.365 [DataOverHttps](INFO): Sending 204 bytes from file Logs/20210902T181929/Courier0033.lzma 2021-09-02T19:20:03.367Z,1630610403.367 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0033.lzma.bak 2021-09-02T19:20:03.367Z,1630610403.367 [DataOverHttps](INFO): SBD MOMSN=15908445 2021-09-02T19:20:19.768Z,1630610419.768 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20210902T181929/Express0034.lzma 2021-09-02T19:20:20.771Z,1630610420.771 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0034.lzma.bak 2021-09-02T19:20:20.771Z,1630610420.771 [DataOverHttps](INFO): SBD MOMSN=15908448 2021-09-02T19:20:22.104Z,1630610422.104 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:20:22.104Z,1630610422.104 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:20:22.104Z,1630610422.104 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:20:25.319Z,1630610425.319 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T19:20:25.393Z,1630610425.393 [NAL9602](ERROR): received: +CSQ:0 OK680, 2, 0, 0, 0 OK 2021-09-02T19:20:40.263Z,1630610440.263 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:20:40.263Z,1630610440.263 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:24:56.414Z,1630610696.414 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:25:22.689Z,1630610722.689 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:25:22.689Z,1630610722.689 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:25:22.689Z,1630610722.689 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:25:22.689Z,1630610722.689 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:25:23.115Z,1630610723.115 [Default:CheckIn:D] Stopped 2021-09-02T19:25:23.116Z,1630610723.116 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:25:23.492Z,1630610723.492 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 125.272314 min 2021-09-02T19:25:23.492Z,1630610723.492 [Default:CheckIn:E] Stopped 2021-09-02T19:25:23.492Z,1630610723.492 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:25:23.492Z,1630610723.492 [Default:CheckIn] Stopped 2021-09-02T19:25:23.493Z,1630610723.493 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:25:23.493Z,1630610723.493 [Default:CheckIn](INFO): Running loop #23 2021-09-02T19:25:23.493Z,1630610723.493 [Default:CheckIn] Running Loop=23 2021-09-02T19:25:23.493Z,1630610723.493 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:25:23.493Z,1630610723.493 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:25:25.509Z,1630610725.509 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192524.00,A,3648.16687,N,12147.27247,W,1.322,0.00,020921,,,D*78 2021-09-02T19:25:25.511Z,1630610725.511 [NAL9602](INFO): GPS fix at 20210902T192524: (36.802781, -121.787875) 2021-09-02T19:25:25.522Z,1630610725.522 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:25:25.522Z,1630610725.522 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:25:32.828Z,1630610732.828 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20210902T181929/Courier0036.lzma 2021-09-02T19:25:33.831Z,1630610733.831 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0036.lzma.bak 2021-09-02T19:25:33.831Z,1630610733.831 [DataOverHttps](INFO): SBD MOMSN=15908451 2021-09-02T19:25:49.849Z,1630610749.849 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20210902T181929/Express0037.lzma 2021-09-02T19:25:50.851Z,1630610750.851 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0037.lzma.bak 2021-09-02T19:25:50.851Z,1630610750.851 [DataOverHttps](INFO): SBD MOMSN=15908454 2021-09-02T19:25:52.215Z,1630610752.215 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:25:52.215Z,1630610752.215 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:25:52.215Z,1630610752.215 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:25:57.438Z,1630610757.438 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T19:30:52.806Z,1630611052.806 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:30:52.806Z,1630611052.806 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:30:52.806Z,1630611052.806 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:30:52.806Z,1630611052.806 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:30:53.215Z,1630611053.215 [Default:CheckIn:D] Stopped 2021-09-02T19:30:53.215Z,1630611053.215 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:30:53.636Z,1630611053.636 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.773975 min 2021-09-02T19:30:53.636Z,1630611053.636 [Default:CheckIn:E] Stopped 2021-09-02T19:30:53.636Z,1630611053.636 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:30:53.636Z,1630611053.636 [Default:CheckIn] Stopped 2021-09-02T19:30:53.636Z,1630611053.636 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:30:53.637Z,1630611053.637 [Default:CheckIn](INFO): Running loop #24 2021-09-02T19:30:53.637Z,1630611053.637 [Default:CheckIn] Running Loop=24 2021-09-02T19:30:53.637Z,1630611053.637 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:30:53.637Z,1630611053.637 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:30:55.620Z,1630611055.620 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193054.00,A,3648.16692,N,12147.28041,W,0.097,50.44,020921,,,D*4D 2021-09-02T19:30:55.622Z,1630611055.622 [NAL9602](INFO): GPS fix at 20210902T193054: (36.802782, -121.788007) 2021-09-02T19:30:55.684Z,1630611055.684 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:30:55.684Z,1630611055.684 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:31:03.460Z,1630611063.460 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0039.lzma 2021-09-02T19:31:04.463Z,1630611064.463 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0039.lzma.bak 2021-09-02T19:31:04.463Z,1630611064.463 [DataOverHttps](INFO): SBD MOMSN=15908458 2021-09-02T19:31:20.437Z,1630611080.437 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20210902T181929/Express0040.lzma 2021-09-02T19:31:21.439Z,1630611081.439 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0040.lzma.bak 2021-09-02T19:31:21.439Z,1630611081.439 [DataOverHttps](INFO): SBD MOMSN=15908461 2021-09-02T19:31:22.706Z,1630611082.706 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:31:22.706Z,1630611082.706 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:31:22.706Z,1630611082.706 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:31:26.318Z,1630611086.318 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T19:31:26.393Z,1630611086.393 [NAL9602](ERROR): received: +CSQ:0 OK680, 2, 0, 0, 0 OK 2021-09-02T19:35:57.410Z,1630611357.410 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:36:23.280Z,1630611383.280 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:36:23.280Z,1630611383.280 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:36:23.280Z,1630611383.280 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:36:23.281Z,1630611383.281 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:36:23.684Z,1630611383.684 [Default:CheckIn:D] Stopped 2021-09-02T19:36:23.684Z,1630611383.684 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:36:24.093Z,1630611384.093 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 136.281795 min 2021-09-02T19:36:24.093Z,1630611384.093 [Default:CheckIn:E] Stopped 2021-09-02T19:36:24.093Z,1630611384.093 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:36:24.093Z,1630611384.093 [Default:CheckIn] Stopped 2021-09-02T19:36:24.093Z,1630611384.093 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:36:24.094Z,1630611384.094 [Default:CheckIn](INFO): Running loop #25 2021-09-02T19:36:24.094Z,1630611384.094 [Default:CheckIn] Running Loop=25 2021-09-02T19:36:24.094Z,1630611384.094 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:36:24.094Z,1630611384.094 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:36:26.096Z,1630611386.096 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193625.00,A,3648.16384,N,12147.28425,W,0.233,50.44,020921,,,D*45 2021-09-02T19:36:26.098Z,1630611386.098 [NAL9602](INFO): GPS fix at 20210902T193625: (36.802731, -121.788071) 2021-09-02T19:36:26.134Z,1630611386.134 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:36:26.134Z,1630611386.134 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:36:33.116Z,1630611393.116 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0042.lzma 2021-09-02T19:36:34.119Z,1630611394.119 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0042.lzma.bak 2021-09-02T19:36:34.119Z,1630611394.119 [DataOverHttps](INFO): SBD MOMSN=15908464 2021-09-02T19:36:52.749Z,1630611412.749 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20210902T181929/Express0043.lzma 2021-09-02T19:36:53.751Z,1630611413.751 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0043.lzma.bak 2021-09-02T19:36:53.751Z,1630611413.751 [DataOverHttps](INFO): SBD MOMSN=15908468 2021-09-02T19:36:55.281Z,1630611415.281 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:36:55.282Z,1630611415.282 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:36:55.282Z,1630611415.282 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:36:58.462Z,1630611418.462 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T19:41:55.824Z,1630611715.824 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:41:55.824Z,1630611715.824 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:41:55.824Z,1630611715.824 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:41:55.824Z,1630611715.824 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:41:56.236Z,1630611716.236 [Default:CheckIn:D] Stopped 2021-09-02T19:41:56.236Z,1630611716.236 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:41:56.650Z,1630611716.650 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.824316 min 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn:E] Stopped 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn] Stopped 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn](INFO): Running loop #26 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn] Running Loop=26 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:41:56.651Z,1630611716.651 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:41:58.639Z,1630611718.639 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194157.00,A,3648.16504,N,12147.28284,W,0.525,62.49,020921,,,A*4A 2021-09-02T19:41:58.641Z,1630611718.641 [NAL9602](INFO): GPS fix at 20210902T194157: (36.802751, -121.788047) 2021-09-02T19:41:58.652Z,1630611718.652 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:41:58.652Z,1630611718.652 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:42:05.900Z,1630611725.900 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20210902T181929/Courier0045.lzma 2021-09-02T19:42:06.903Z,1630611726.903 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0045.lzma.bak 2021-09-02T19:42:06.903Z,1630611726.903 [DataOverHttps](INFO): SBD MOMSN=15908472 2021-09-02T19:42:23.488Z,1630611743.488 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20210902T181929/Express0046.lzma 2021-09-02T19:42:24.491Z,1630611744.491 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0046.lzma.bak 2021-09-02T19:42:24.491Z,1630611744.491 [DataOverHttps](INFO): SBD MOMSN=15908475 2021-09-02T19:42:25.718Z,1630611745.718 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:42:25.718Z,1630611745.718 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:42:25.718Z,1630611745.718 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:42:29.346Z,1630611749.346 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T19:42:29.421Z,1630611749.421 [NAL9602](ERROR): received: +CSQ:0 OK680, 2, 0, 0, 0 OK 2021-09-02T19:45:42.454Z,1630611942.454 [NAL9602](INFO): SBD MO Status=2, MOMSN=29680, MT Status=2, MTMSN=0 2021-09-02T19:45:42.454Z,1630611942.454 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2021-09-02T19:47:01.232Z,1630612021.232 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:47:26.290Z,1630612046.290 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:47:26.290Z,1630612046.290 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:47:26.290Z,1630612046.290 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:47:26.290Z,1630612046.290 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:47:26.706Z,1630612046.706 [Default:CheckIn:D] Stopped 2021-09-02T19:47:26.706Z,1630612046.706 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 147.332161 min 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn:E] Stopped 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn] Stopped 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn](INFO): Running loop #27 2021-09-02T19:47:27.096Z,1630612047.096 [Default:CheckIn] Running Loop=27 2021-09-02T19:47:27.097Z,1630612047.097 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:47:27.097Z,1630612047.097 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:47:29.133Z,1630612049.133 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194728.00,A,3648.11115,N,12147.26451,W,0.991,142.56,020921,,,A*79 2021-09-02T19:47:29.135Z,1630612049.135 [NAL9602](INFO): GPS fix at 20210902T194728: (36.801853, -121.787742) 2021-09-02T19:47:29.146Z,1630612049.146 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:47:29.146Z,1630612049.146 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:47:36.760Z,1630612056.760 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20210902T181929/Courier0048.lzma 2021-09-02T19:47:37.763Z,1630612057.763 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0048.lzma.bak 2021-09-02T19:47:37.763Z,1630612057.763 [DataOverHttps](INFO): SBD MOMSN=15908479 2021-09-02T19:47:54.117Z,1630612074.117 [DataOverHttps](INFO): Sending 221 bytes from file Logs/20210902T181929/Express0049.lzma 2021-09-02T19:47:55.119Z,1630612075.119 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0049.lzma.bak 2021-09-02T19:47:55.119Z,1630612075.119 [DataOverHttps](INFO): SBD MOMSN=15908483 2021-09-02T19:47:56.592Z,1630612076.592 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:47:56.592Z,1630612076.592 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:47:56.592Z,1630612076.592 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:48:01.430Z,1630612081.430 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T19:52:57.174Z,1630612377.174 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T19:52:57.174Z,1630612377.174 [Default:CheckIn:C.Wait] Stopped 2021-09-02T19:52:57.174Z,1630612377.174 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T19:52:57.175Z,1630612377.175 [Default:CheckIn:D] Running Loop=1 2021-09-02T19:52:57.591Z,1630612377.591 [Default:CheckIn:D] Stopped 2021-09-02T19:52:57.591Z,1630612377.591 [Default:CheckIn:E] Running Loop=1 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 152.846908 min 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn:E] Stopped 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn] Stopped 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn](INFO): Running loop #28 2021-09-02T19:52:57.980Z,1630612377.980 [Default:CheckIn] Running Loop=28 2021-09-02T19:52:57.981Z,1630612377.981 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T19:52:57.981Z,1630612377.981 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T19:53:30.697Z,1630612410.697 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-09-02T19:53:30.777Z,1630612410.777 [NAL9602](ERROR): received: +CSQ:0 OK680, 2, 0, 0, 0 OK 2021-09-02T19:57:58.157Z,1630612678.157 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-02T19:52:57.0Z 2021-09-02T19:57:58.157Z,1630612678.157 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T19:57:58.157Z,1630612678.157 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T19:58:02.182Z,1630612682.182 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T19:58:05.264Z,1630612685.264 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210902T181929/Courier0051.lzma 2021-09-02T19:58:06.279Z,1630612686.279 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0051.lzma.bak 2021-09-02T19:58:06.279Z,1630612686.279 [DataOverHttps](INFO): SBD MOMSN=15908488 2021-09-02T19:58:13.498Z,1630612693.498 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2021-09-02T19:58:13.498Z,1630612693.498 [DropWeight] Hardware Fault, FailCount= 1 2021-09-02T19:58:13.498Z,1630612693.498 [DropWeight](ERROR): Hardware Fault 2021-09-02T19:58:13.541Z,1630612693.541 [CommandExec](FAULT): Scheduling is paused 2021-09-02T19:58:13.545Z,1630612693.545 [CBIT](INFO): Critical error at 20210902T195813 2021-09-02T19:58:13.548Z,1630612693.548 [CBIT](ERROR): Hardware Fault in component: DropWeight 2021-09-02T19:58:13.548Z,1630612693.548 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2021-09-02T19:58:13.950Z,1630612693.950 [CBIT](INFO): Critical error at 20210902T195813 2021-09-02T19:58:22.424Z,1630612702.424 [DataOverHttps](INFO): Sending 132 bytes from file Logs/20210902T181929/Express0052.lzma 2021-09-02T19:58:23.427Z,1630612703.427 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0052.lzma.bak 2021-09-02T19:58:23.427Z,1630612703.427 [DataOverHttps](INFO): SBD MOMSN=15908490 2021-09-02T19:58:24.822Z,1630612704.822 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T19:58:24.822Z,1630612704.822 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T19:58:24.822Z,1630612704.822 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T19:58:32.890Z,1630612712.890 [NAL9602](INFO): Not Powering down - fast GPS 2021-09-02T20:03:25.428Z,1630613005.428 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-09-02T20:03:25.428Z,1630613005.428 [Default:CheckIn:C.Wait] Stopped 2021-09-02T20:03:25.428Z,1630613005.428 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T20:03:25.428Z,1630613005.428 [Default:CheckIn:D] Running Loop=1 2021-09-02T20:03:25.836Z,1630613005.836 [Default:CheckIn:D] Stopped 2021-09-02T20:03:25.836Z,1630613005.836 [Default:CheckIn:E] Running Loop=1 2021-09-02T20:03:26.232Z,1630613006.232 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 163.317660 min 2021-09-02T20:03:26.233Z,1630613006.233 [Default:CheckIn:E] Stopped 2021-09-02T20:03:26.233Z,1630613006.233 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-09-02T20:03:26.233Z,1630613006.233 [Default:CheckIn] Stopped 2021-09-02T20:03:26.234Z,1630613006.234 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T20:03:26.234Z,1630613006.234 [Default:CheckIn](INFO): Running loop #29 2021-09-02T20:03:26.234Z,1630613006.234 [Default:CheckIn] Running Loop=29 2021-09-02T20:03:26.234Z,1630613006.234 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-09-02T20:03:26.234Z,1630613006.234 [Default:CheckIn:Read_GPS] Running Loop=1 2021-09-02T20:03:27.838Z,1630613007.838 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-09-02T20:03:27.838Z,1630613007.838 [NAL9602] Data Fault, FailCount= 1 2021-09-02T20:03:27.838Z,1630613007.838 [NAL9602](ERROR): Data Fault 2021-09-02T20:03:27.883Z,1630613007.883 [CBIT](ERROR): Data Fault in component: NAL9602 2021-09-02T20:03:28.242Z,1630613008.242 [NAL9602](INFO): Powering down 2021-09-02T20:03:28.642Z,1630613008.642 [NAL9602](FAULT): LCB fault: Software Overcurrent. 2021-09-02T20:03:28.642Z,1630613008.642 [NAL9602] Hardware Fault, FailCount= 1 2021-09-02T20:03:28.642Z,1630613008.642 [NAL9602](ERROR): Hardware Fault 2021-09-02T20:03:29.096Z,1630613009.096 [CBIT](INFO): Clearing failed state for component NAL9602 2021-09-02T20:03:29.096Z,1630613009.096 [NAL9602] No Fault, FailCount= 1 2021-09-02T20:03:58.541Z,1630613038.541 [NAL9602](INFO): Powering up NAL9602 2021-09-02T20:04:09.450Z,1630613049.450 [NAL9602](INFO): NAL9602 initialized 2021-09-02T20:08:26.417Z,1630613306.417 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-09-02T20:03:26.2Z 2021-09-02T20:08:26.417Z,1630613306.417 [Default:CheckIn:Read_GPS] Stopped 2021-09-02T20:08:26.418Z,1630613306.418 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-09-02T20:08:34.145Z,1630613314.145 [DataOverHttps](INFO): Sending 148 bytes from file Logs/20210902T181929/Courier0054.lzma 2021-09-02T20:08:35.147Z,1630613315.147 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Courier0054.lzma.bak 2021-09-02T20:08:35.147Z,1630613315.147 [DataOverHttps](INFO): SBD MOMSN=15908494 2021-09-02T20:08:53.680Z,1630613333.680 [DataOverHttps](INFO): Sending 280 bytes from file Logs/20210902T181929/Express0055.lzma 2021-09-02T20:08:54.691Z,1630613334.691 [DataOverHttps](INFO): Moved sent file to Logs/20210902T181929/Express0055.lzma.bak 2021-09-02T20:08:54.691Z,1630613334.691 [DataOverHttps](INFO): SBD MOMSN=15908498 2021-09-02T20:08:55.930Z,1630613335.930 [Default:CheckIn:Read_Iridium] Stopped 2021-09-02T20:08:55.930Z,1630613335.930 [Default:CheckIn:C.Wait] Running Loop=1 2021-09-02T20:08:55.930Z,1630613335.930 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-09-02T20:09:09.414Z,1630613349.414 [CommandExec](IMPORTANT): got command quit 2021-09-02T20:09:10.417Z,1630613350.417 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:10.417Z,1630613350.417 [CommandExec](INFO): Uninitializing the command executive. 2021-09-02T20:09:10.417Z,1630613350.417 [CommandExec](INFO): Uninitializing the command scheduler. 2021-09-02T20:09:10.417Z,1630613350.417 [CommandExec ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.605Z,1630613350.605 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2021-09-02T20:09:10.605Z,1630613350.605 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2021-09-02T20:09:10.605Z,1630613350.605 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.606Z,1630613350.606 [NavChartDb](INFO): Join timeout helper Thread ID is 3128 2021-09-02T20:09:10.857Z,1630613350.857 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:10.857Z,1630613350.857 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.869Z,1630613350.869 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2021-09-02T20:09:10.869Z,1630613350.869 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.869Z,1630613350.869 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 3129 2021-09-02T20:09:10.965Z,1630613350.965 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:10.966Z,1630613350.966 [WetLabsBB2FL](INFO): Powering down 2021-09-02T20:09:10.966Z,1630613350.966 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.985Z,1630613350.985 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2021-09-02T20:09:10.985Z,1630613350.985 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:10.985Z,1630613350.985 [CTD_Seabird](INFO): Join timeout helper Thread ID is 3130 2021-09-02T20:09:11.461Z,1630613351.461 [CTD_Seabird](INFO): Powering down 2021-09-02T20:09:11.473Z,1630613351.473 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:11.473Z,1630613351.473 [CTD_Seabird](INFO): Powering down 2021-09-02T20:09:11.485Z,1630613351.485 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:11.498Z,1630613351.498 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2021-09-02T20:09:11.498Z,1630613351.498 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:11.498Z,1630613351.498 [Radio_Surface](INFO): Join timeout helper Thread ID is 3131 2021-09-02T20:09:11.893Z,1630613351.893 [Radio_Surface](INFO): Powering down 2021-09-02T20:09:11.894Z,1630613351.894 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:11.894Z,1630613351.894 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:11.897Z,1630613351.897 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2021-09-02T20:09:11.897Z,1630613351.897 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:11.897Z,1630613351.897 [Onboard](INFO): Join timeout helper Thread ID is 3132 2021-09-02T20:09:12.301Z,1630613352.301 [DataOverHttps](INFO): Radio surface powered OFF, will not connect. 2021-09-02T20:09:12.858Z,1630613352.858 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-09-02T20:09:15.213Z,1630613355.213 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:15.213Z,1630613355.213 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.234Z,1630613355.234 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2021-09-02T20:09:15.234Z,1630613355.234 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.234Z,1630613355.234 [DataOverHttps](INFO): Join timeout helper Thread ID is 3133 2021-09-02T20:09:15.313Z,1630613355.313 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:15.313Z,1630613355.313 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.315Z,1630613355.315 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2021-09-02T20:09:15.315Z,1630613355.315 [logger ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.315Z,1630613355.315 [logger](INFO): Join timeout helper Thread ID is 3134 2021-09-02T20:09:15.363Z,1630613355.363 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:15.364Z,1630613355.364 [logger ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.378Z,1630613355.378 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2021-09-02T20:09:15.378Z,1630613355.378 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.378Z,1630613355.378 [CommandLine](INFO): Join timeout helper Thread ID is 3135 2021-09-02T20:09:15.389Z,1630613355.389 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:15.389Z,1630613355.389 [CommandLine ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.398Z,1630613355.398 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler 2021-09-02T20:09:15.398Z,1630613355.398 [CommandExec ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.398Z,1630613355.398 [CommandExec](INFO): Join timeout helper Thread ID is 3136 2021-09-02T20:09:15.399Z,1630613355.399 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2021-09-02T20:09:15.400Z,1630613355.400 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.400Z,1630613355.400 [controlThread](INFO): Join timeout helper Thread ID is 3137 2021-09-02T20:09:15.661Z,1630613355.661 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2021-09-02T20:09:15.661Z,1630613355.661 [controlThread](DEBUG): Uninitializing ControlThread 2021-09-02T20:09:15.662Z,1630613355.662 [AHRS_M2](INFO): Powering down 2021-09-02T20:09:15.734Z,1630613355.734 [NAL9602](INFO): Powering down 2021-09-02T20:09:15.736Z,1630613355.736 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2021-09-02T20:09:15.738Z,1630613355.738 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2021-09-02T20:09:15.738Z,1630613355.738 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2021-09-02T20:09:15.739Z,1630613355.739 [MissionManager](INFO): Uninitializing Mission Default 2021-09-02T20:09:15.739Z,1630613355.739 [Default] Stopped 2021-09-02T20:09:15.739Z,1630613355.739 [Default](DEBUG): Aggregate::uninitialize Default 2021-09-02T20:09:15.739Z,1630613355.739 [Default:B.GoToSurface] Stopped 2021-09-02T20:09:15.739Z,1630613355.739 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-09-02T20:09:15.739Z,1630613355.739 [Default:CheckIn] Stopped 2021-09-02T20:09:15.739Z,1630613355.739 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-09-02T20:09:15.739Z,1630613355.739 [Default:CheckIn:C.Wait] Stopped 2021-09-02T20:09:15.739Z,1630613355.739 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-09-02T20:09:15.743Z,1630613355.743 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2021-09-02T20:09:15.743Z,1630613355.743 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2021-09-02T20:09:15.743Z,1630613355.743 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2021-09-02T20:09:15.744Z,1630613355.744 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2021-09-02T20:09:15.744Z,1630613355.744 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2021-09-02T20:09:15.744Z,1630613355.744 [BuoyancyServo](INFO): Powering down 2021-09-02T20:09:15.757Z,1630613355.757 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2021-09-02T20:09:15.757Z,1630613355.757 [ElevatorServo](INFO): Powering down 2021-09-02T20:09:15.758Z,1630613355.758 [MassServo](DEBUG): Uninitialize Mass Servo. 2021-09-02T20:09:15.758Z,1630613355.758 [MassServo](INFO): Powering down 2021-09-02T20:09:15.759Z,1630613355.759 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2021-09-02T20:09:15.759Z,1630613355.759 [RudderServo](INFO): Powering down 2021-09-02T20:09:15.760Z,1630613355.760 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2021-09-02T20:09:15.760Z,1630613355.760 [ThrusterServo](INFO): Powering down 2021-09-02T20:09:15.761Z,1630613355.761 [SBIT](DEBUG): Uninitialize SBIT Component. 2021-09-02T20:09:15.762Z,1630613355.762 [IBIT](DEBUG): Uninitialize IBIT Component. 2021-09-02T20:09:15.762Z,1630613355.762 [CBIT](DEBUG): Uninitialize CBIT Component. 2021-09-02T20:09:15.762Z,1630613355.762 [CBIT](DEBUG): Powering off loads. 2021-09-02T20:09:15.773Z,1630613355.773 [CBIT](DEBUG): Disabling WDT. 2021-09-02T20:09:15.785Z,1630613355.785 [CBIT](DEBUG): Opening all GF detection circuits. 2021-09-02T20:09:15.786Z,1630613355.786 [controlThread ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.834Z,1630613355.834 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.837Z,1630613355.837 [Onboard ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.843Z,1630613355.843 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.914Z,1630613355.914 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.918Z,1630613355.918 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:15.962Z,1630613355.962 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2021-09-02T20:09:16.034Z,1630613356.034 [logger ThreadHandler](INFO): Thread cancelled.