2022-05-19T17:31:03.968Z,1652981463.968 [CommandExec](IMPORTANT): got command restart logs 2022-05-19T17:31:14.507Z,1652981474.507 [NAL9602](INFO): SBD MO Status=2, MOMSN=19321, MT Status=2, MTMSN=0 2022-05-19T17:31:14.507Z,1652981474.507 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:31:24.203Z,1652981484.203 [NAL9602](INFO): SBD MO Status=0, MOMSN=19321, MT Status=0, MTMSN=0 2022-05-19T17:31:24.203Z,1652981484.203 [NAL9602](INFO): No messages in MT queue 2022-05-19T17:31:54.911Z,1652981514.911 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T17:33:20.819Z,1652981600.819 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.267422 2022-05-19T17:34:02.631Z,1652981642.631 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003427 2022-05-19T17:35:11.262Z,1652981711.262 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T17:35:11.262Z,1652981711.262 [Default:CheckIn:C.Wait] Stopped 2022-05-19T17:35:11.262Z,1652981711.262 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T17:35:11.262Z,1652981711.262 [Default:CheckIn:D] Running Loop=1 2022-05-19T17:35:11.675Z,1652981711.675 [Default:CheckIn:D] Stopped 2022-05-19T17:35:11.676Z,1652981711.676 [Default:CheckIn:E] Running Loop=1 2022-05-19T17:35:12.074Z,1652981712.074 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 52.819153 min 2022-05-19T17:35:12.074Z,1652981712.074 [Default:CheckIn:E] Stopped 2022-05-19T17:35:12.074Z,1652981712.074 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T17:35:12.094Z,1652981712.094 [Default:CheckIn] Stopped 2022-05-19T17:35:12.094Z,1652981712.094 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T17:35:12.094Z,1652981712.094 [Default:CheckIn](INFO): Running loop #9 2022-05-19T17:35:12.095Z,1652981712.095 [Default:CheckIn] Running Loop=9 2022-05-19T17:35:12.095Z,1652981712.095 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T17:35:12.095Z,1652981712.095 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T17:35:14.082Z,1652981714.082 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173513.00,A,3649.82243,N,12152.21330,W,0.739,56.45,190522,,,D*48 2022-05-19T17:35:14.084Z,1652981714.084 [NAL9602](INFO): GPS fix at 20220519T173513: (36.830374, -121.870222) 2022-05-19T17:35:14.095Z,1652981714.095 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T17:35:14.095Z,1652981714.095 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T17:35:29.835Z,1652981729.835 [NAL9602](INFO): SBD MO Status=0, MOMSN=19322, MT Status=0, MTMSN=0 2022-05-19T17:35:29.836Z,1652981729.836 [NAL9602](INFO): No messages in MT queue 2022-05-19T17:35:36.527Z,1652981736.527 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:35:38.535Z,1652981738.535 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.239017 2022-05-19T17:36:05.057Z,1652981765.057 [NAL9602](INFO): SBD MO Status=2, MOMSN=19323, MT Status=2, MTMSN=0 2022-05-19T17:36:05.057Z,1652981765.057 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:36:09.670Z,1652981769.670 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:36:31.001Z,1652981791.001 [NAL9602](INFO): SBD MO Status=2, MOMSN=19323, MT Status=2, MTMSN=0 2022-05-19T17:36:31.001Z,1652981791.001 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:36:44.811Z,1652981804.811 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:37:08.651Z,1652981828.651 [NAL9602](INFO): SBD MO Status=2, MOMSN=19323, MT Status=2, MTMSN=0 2022-05-19T17:37:08.651Z,1652981828.651 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:37:19.983Z,1652981839.983 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:37:33.357Z,1652981853.357 [NAL9602](INFO): SBD MO Status=1, MOMSN=19323, MT Status=0, MTMSN=0 2022-05-19T17:37:33.406Z,1652981853.406 [NAL9602](INFO): Sent 39 bytes from file Logs/20220518T182753/Courier0102.lzma 2022-05-19T17:37:33.407Z,1652981853.407 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:37:44.747Z,1652981864.747 [NAL9602](INFO): SBD MO Status=1, MOMSN=19324, MT Status=0, MTMSN=0 2022-05-19T17:37:44.802Z,1652981864.802 [NAL9602](INFO): Sent 267 bytes from file Logs/20220519T173103/Courier0000.lzma 2022-05-19T17:37:44.803Z,1652981864.803 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:37:55.122Z,1652981875.122 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:37:56.169Z,1652981876.169 [NAL9602](INFO): SBD MO Status=1, MOMSN=19325, MT Status=0, MTMSN=0 2022-05-19T17:37:56.230Z,1652981876.230 [NAL9602](INFO): Sent 138 bytes from file Logs/20220518T182753/Express0103.lzma 2022-05-19T17:37:56.231Z,1652981876.231 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:38:09.563Z,1652981889.563 [NAL9602](INFO): SBD MO Status=1, MOMSN=19326, MT Status=0, MTMSN=0 2022-05-19T17:38:09.618Z,1652981889.618 [NAL9602](INFO): Sent 332 bytes from file Logs/20220519T173103/Express0001.lzma 2022-05-19T17:38:09.619Z,1652981889.619 [NAL9602](INFO): Packets left to send: 1 2022-05-19T17:38:19.317Z,1652981899.317 [NAL9602](INFO): SBD MO Status=1, MOMSN=19327, MT Status=0, MTMSN=0 2022-05-19T17:38:19.366Z,1652981899.366 [NAL9602](INFO): Sent 47 bytes from file Logs/20220519T173103/Express0001.lzma 2022-05-19T17:38:19.367Z,1652981899.367 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:38:41.214Z,1652981921.214 [NAL9602](INFO): SBD MO Status=1, MOMSN=19328, MT Status=0, MTMSN=0 2022-05-19T17:38:41.270Z,1652981921.270 [NAL9602](INFO): Sent 61 bytes from file Logs/20220519T173103/Express0004.lzma 2022-05-19T17:38:41.271Z,1652981921.271 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:39:01.005Z,1652981941.005 [NAL9602](INFO): SBD MO Status=2, MOMSN=19329, MT Status=2, MTMSN=0 2022-05-19T17:39:01.005Z,1652981941.005 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:39:22.821Z,1652981962.821 [NAL9602](INFO): SBD MO Status=2, MOMSN=19329, MT Status=2, MTMSN=0 2022-05-19T17:39:22.821Z,1652981962.821 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:39:42.078Z,1652981982.078 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:39:42.613Z,1652981982.613 [NAL9602](INFO): SBD MO Status=2, MOMSN=19329, MT Status=2, MTMSN=0 2022-05-19T17:39:42.614Z,1652981982.614 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:40:06.457Z,1652982006.457 [NAL9602](INFO): SBD MO Status=2, MOMSN=19329, MT Status=2, MTMSN=0 2022-05-19T17:40:06.457Z,1652982006.457 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:40:11.011Z,1652982011.011 [NAL9602](ERROR): Inadequate Iridium signal strength reported: 0 2022-05-19T17:40:17.218Z,1652982017.218 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:40:39.981Z,1652982039.981 [NAL9602](INFO): SBD MO Status=0, MOMSN=19329, MT Status=0, MTMSN=0 2022-05-19T17:40:40.063Z,1652982040.063 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T17:40:40.063Z,1652982040.063 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T17:40:40.063Z,1652982040.063 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T17:41:10.717Z,1652982070.717 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T17:41:41.879Z,1652982101.879 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003419 2022-05-19T17:43:14.691Z,1652982194.691 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:43:16.700Z,1652982196.700 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.275726 2022-05-19T17:44:37.755Z,1652982277.755 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003309 2022-05-19T17:45:37.991Z,1652982337.991 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.238804 2022-05-19T17:45:40.569Z,1652982340.569 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T17:45:40.570Z,1652982340.570 [Default:CheckIn:C.Wait] Stopped 2022-05-19T17:45:40.570Z,1652982340.570 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T17:45:40.570Z,1652982340.570 [Default:CheckIn:D] Running Loop=1 2022-05-19T17:45:40.993Z,1652982340.993 [Default:CheckIn:D] Stopped 2022-05-19T17:45:40.993Z,1652982340.993 [Default:CheckIn:E] Running Loop=1 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 63.307776 min 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn:E] Stopped 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn] Stopped 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T17:45:41.382Z,1652982341.382 [Default:CheckIn](INFO): Running loop #10 2022-05-19T17:45:41.383Z,1652982341.383 [Default:CheckIn] Running Loop=10 2022-05-19T17:45:41.383Z,1652982341.383 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T17:45:41.383Z,1652982341.383 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T17:45:43.384Z,1652982343.384 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174542.00,A,3649.48858,N,12151.17094,W,24.706,113.32,190522,,,D*4C 2022-05-19T17:45:43.386Z,1652982343.386 [NAL9602](INFO): GPS fix at 20220519T174542: (36.824810, -121.852849) 2022-05-19T17:45:43.423Z,1652982343.423 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T17:45:43.423Z,1652982343.423 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T17:46:05.666Z,1652982365.666 [NAL9602](INFO): SBD MO Status=2, MOMSN=19330, MT Status=2, MTMSN=0 2022-05-19T17:46:05.666Z,1652982365.666 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:46:11.126Z,1652982371.126 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:46:25.553Z,1652982385.553 [NAL9602](INFO): SBD MO Status=1, MOMSN=19330, MT Status=0, MTMSN=0 2022-05-19T17:46:25.615Z,1652982385.615 [NAL9602](INFO): Sent 73 bytes from file Logs/20220519T173103/Courier0006.lzma 2022-05-19T17:46:25.615Z,1652982385.615 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:46:36.515Z,1652982396.515 [NAL9602](INFO): SBD MO Status=1, MOMSN=19331, MT Status=0, MTMSN=0 2022-05-19T17:46:36.569Z,1652982396.569 [NAL9602](INFO): Sent 143 bytes from file Logs/20220519T173103/Express0007.lzma 2022-05-19T17:46:36.569Z,1652982396.569 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:46:46.259Z,1652982406.259 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003994 2022-05-19T17:46:47.451Z,1652982407.451 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T17:46:47.451Z,1652982407.451 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T17:46:47.451Z,1652982407.451 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T17:46:56.732Z,1652982416.732 [NAL9602](INFO): SBD MO Status=2, MOMSN=19332, MT Status=2, MTMSN=0 2022-05-19T17:46:56.732Z,1652982416.732 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T17:47:27.426Z,1652982447.426 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T17:50:19.015Z,1652982619.015 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.983349 2022-05-19T17:50:38.791Z,1652982638.791 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003383 2022-05-19T17:51:27.991Z,1652982687.991 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:51:39.553Z,1652982699.553 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.765133 2022-05-19T17:51:48.013Z,1652982708.013 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T17:51:48.013Z,1652982708.013 [Default:CheckIn:C.Wait] Stopped 2022-05-19T17:51:48.013Z,1652982708.013 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T17:51:48.013Z,1652982708.013 [Default:CheckIn:D] Running Loop=1 2022-05-19T17:51:48.417Z,1652982708.417 [Default:CheckIn:D] Stopped 2022-05-19T17:51:48.417Z,1652982708.417 [Default:CheckIn:E] Running Loop=1 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 69.431519 min 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn:E] Stopped 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn] Stopped 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn](INFO): Running loop #11 2022-05-19T17:51:48.841Z,1652982708.841 [Default:CheckIn] Running Loop=11 2022-05-19T17:51:48.842Z,1652982708.842 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T17:51:48.842Z,1652982708.842 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T17:51:50.827Z,1652982710.827 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175150.00,A,3648.45509,N,12149.26008,W,9.952,103.81,190522,,,D*78 2022-05-19T17:51:50.829Z,1652982710.829 [NAL9602](INFO): GPS fix at 20220519T175150: (36.807585, -121.821001) 2022-05-19T17:51:50.876Z,1652982710.876 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T17:51:50.876Z,1652982710.876 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T17:52:05.829Z,1652982725.829 [NAL9602](INFO): SBD MO Status=1, MOMSN=19332, MT Status=0, MTMSN=0 2022-05-19T17:52:05.879Z,1652982725.879 [NAL9602](INFO): Sent 73 bytes from file Logs/20220519T173103/Courier0009.lzma 2022-05-19T17:52:05.879Z,1652982725.879 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:52:15.237Z,1652982735.237 [NAL9602](INFO): SBD MO Status=1, MOMSN=19333, MT Status=0, MTMSN=0 2022-05-19T17:52:15.287Z,1652982735.287 [NAL9602](INFO): Sent 142 bytes from file Logs/20220519T173103/Express0010.lzma 2022-05-19T17:52:15.287Z,1652982735.287 [NAL9602](INFO): Packets left to send: 0 2022-05-19T17:52:22.917Z,1652982742.917 [NAL9602](INFO): SBD MO Status=0, MOMSN=19334, MT Status=0, MTMSN=0 2022-05-19T17:52:23.018Z,1652982743.018 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T17:52:23.020Z,1652982743.020 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T17:52:23.020Z,1652982743.020 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T17:52:38.783Z,1652982758.783 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:52:53.675Z,1652982773.675 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T17:53:13.922Z,1652982793.922 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T17:54:24.955Z,1652982864.955 [DataOverHttps](INFO): Exceeded connection timeout, disconnecting. 2022-05-19T17:55:13.900Z,1652982913.900 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.004021 2022-05-19T17:57:23.517Z,1652983043.517 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T17:57:23.517Z,1652983043.517 [Default:CheckIn:C.Wait] Stopped 2022-05-19T17:57:23.517Z,1652983043.517 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T17:57:23.517Z,1652983043.517 [Default:CheckIn:D] Running Loop=1 2022-05-19T17:57:23.923Z,1652983043.923 [Default:CheckIn:D] Stopped 2022-05-19T17:57:23.923Z,1652983043.923 [Default:CheckIn:E] Running Loop=1 2022-05-19T17:57:24.310Z,1652983044.310 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.023283 min 2022-05-19T17:57:24.310Z,1652983044.310 [Default:CheckIn:E] Stopped 2022-05-19T17:57:24.310Z,1652983044.310 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T17:57:24.310Z,1652983044.310 [Default:CheckIn] Stopped 2022-05-19T17:57:24.310Z,1652983044.310 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T17:57:24.311Z,1652983044.311 [Default:CheckIn](INFO): Running loop #12 2022-05-19T17:57:24.311Z,1652983044.311 [Default:CheckIn] Running Loop=12 2022-05-19T17:57:24.311Z,1652983044.311 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T17:57:24.311Z,1652983044.311 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T17:57:26.317Z,1652983046.317 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175725.00,A,3648.50716,N,12147.18569,W,6.803,64.20,190522,,,D*44 2022-05-19T17:57:26.320Z,1652983046.320 [NAL9602](INFO): GPS fix at 20220519T175725: (36.808453, -121.786428) 2022-05-19T17:57:26.330Z,1652983046.330 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T17:57:26.330Z,1652983046.330 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T17:57:33.602Z,1652983053.602 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0012.lzma 2022-05-19T17:57:34.604Z,1652983054.604 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0012.lzma.bak 2022-05-19T17:57:34.604Z,1652983054.604 [DataOverHttps](INFO): SBD MOMSN=16809647 2022-05-19T17:57:49.749Z,1652983069.749 [NAL9602](INFO): SBD MO Status=0, MOMSN=19335, MT Status=0, MTMSN=0 2022-05-19T17:57:49.749Z,1652983069.749 [NAL9602](INFO): No messages in MT queue 2022-05-19T17:57:50.974Z,1652983070.974 [DataOverHttps](INFO): Sending 139 bytes from file Logs/20220519T173103/Express0013.lzma 2022-05-19T17:57:51.976Z,1652983071.976 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0013.lzma.bak 2022-05-19T17:57:51.976Z,1652983071.976 [DataOverHttps](INFO): SBD MOMSN=16809650 2022-05-19T17:57:53.393Z,1652983073.393 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T17:57:53.394Z,1652983073.394 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T17:57:53.394Z,1652983073.394 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T17:58:20.451Z,1652983100.451 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T17:59:15.017Z,1652983155.017 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2022-05-19T18:02:53.967Z,1652983373.967 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:02:53.967Z,1652983373.967 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:02:53.967Z,1652983373.967 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:02:53.968Z,1652983373.968 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:02:54.373Z,1652983374.373 [Default:CheckIn:D] Stopped 2022-05-19T18:02:54.374Z,1652983374.374 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:02:54.804Z,1652983374.804 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 80.530786 min 2022-05-19T18:02:54.804Z,1652983374.804 [Default:CheckIn:E] Stopped 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn] Stopped 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn](INFO): Running loop #13 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn] Running Loop=13 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:02:54.805Z,1652983374.805 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:02:56.789Z,1652983376.789 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180256.00,A,3648.19096,N,12147.16694,W,2.352,207.66,190522,,,D*7C 2022-05-19T18:02:56.792Z,1652983376.792 [NAL9602](INFO): GPS fix at 20220519T180256: (36.803183, -121.786116) 2022-05-19T18:02:56.841Z,1652983376.841 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:02:56.841Z,1652983376.841 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:03:04.398Z,1652983384.398 [DataOverHttps](INFO): Sending 71 bytes from file Logs/20220519T173103/Courier0015.lzma 2022-05-19T18:03:05.400Z,1652983385.400 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0015.lzma.bak 2022-05-19T18:03:05.400Z,1652983385.400 [DataOverHttps](INFO): SBD MOMSN=16809672 2022-05-19T18:03:21.782Z,1652983401.782 [DataOverHttps](INFO): Sending 136 bytes from file Logs/20220519T173103/Express0016.lzma 2022-05-19T18:03:22.784Z,1652983402.784 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0016.lzma.bak 2022-05-19T18:03:22.784Z,1652983402.784 [DataOverHttps](INFO): SBD MOMSN=16809678 2022-05-19T18:03:24.307Z,1652983404.307 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:03:24.307Z,1652983404.307 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:03:24.307Z,1652983404.307 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:03:47.693Z,1652983427.693 [NAL9602](INFO): SBD MO Status=0, MOMSN=19336, MT Status=0, MTMSN=0 2022-05-19T18:03:47.693Z,1652983427.693 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:04:18.395Z,1652983458.395 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:08:24.869Z,1652983704.869 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:08:24.869Z,1652983704.869 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:08:24.869Z,1652983704.869 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:08:24.869Z,1652983704.869 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:08:25.283Z,1652983705.283 [Default:CheckIn:D] Stopped 2022-05-19T18:08:25.283Z,1652983705.283 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:08:25.656Z,1652983705.656 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.045947 min 2022-05-19T18:08:25.656Z,1652983705.656 [Default:CheckIn:E] Stopped 2022-05-19T18:08:25.656Z,1652983705.656 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:08:25.656Z,1652983705.656 [Default:CheckIn] Stopped 2022-05-19T18:08:25.657Z,1652983705.657 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:08:25.657Z,1652983705.657 [Default:CheckIn](INFO): Running loop #14 2022-05-19T18:08:25.657Z,1652983705.657 [Default:CheckIn] Running Loop=14 2022-05-19T18:08:25.657Z,1652983705.657 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:08:25.657Z,1652983705.657 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:08:27.665Z,1652983707.665 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,180826.00,A,3648.12121,N,12147.23142,W,0.039,278.15,190522,,,D*7D 2022-05-19T18:08:27.667Z,1652983707.667 [NAL9602](INFO): GPS fix at 20220519T180826: (36.802020, -121.787190) 2022-05-19T18:08:27.678Z,1652983707.678 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:08:27.678Z,1652983707.678 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:08:35.454Z,1652983715.454 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0018.lzma 2022-05-19T18:08:36.456Z,1652983716.456 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0018.lzma.bak 2022-05-19T18:08:36.457Z,1652983716.457 [DataOverHttps](INFO): SBD MOMSN=16809706 2022-05-19T18:08:38.173Z,1652983718.173 [NAL9602](INFO): SBD MO Status=0, MOMSN=19337, MT Status=0, MTMSN=0 2022-05-19T18:08:38.173Z,1652983718.173 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:08:52.658Z,1652983732.658 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220519T173103/Express0019.lzma 2022-05-19T18:08:53.660Z,1652983733.660 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0019.lzma.bak 2022-05-19T18:08:53.660Z,1652983733.660 [DataOverHttps](INFO): SBD MOMSN=16809709 2022-05-19T18:08:55.170Z,1652983735.170 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:08:55.170Z,1652983735.170 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:08:55.170Z,1652983735.170 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:09:08.875Z,1652983748.875 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:13:55.721Z,1652984035.721 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:13:55.721Z,1652984035.721 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:13:55.721Z,1652984035.721 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:13:55.721Z,1652984035.721 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:13:56.137Z,1652984036.137 [Default:CheckIn:D] Stopped 2022-05-19T18:13:56.137Z,1652984036.137 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:13:56.535Z,1652984036.535 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 91.560173 min 2022-05-19T18:13:56.535Z,1652984036.535 [Default:CheckIn:E] Stopped 2022-05-19T18:13:56.535Z,1652984036.535 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:13:56.535Z,1652984036.535 [Default:CheckIn] Stopped 2022-05-19T18:13:56.536Z,1652984036.536 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:13:56.536Z,1652984036.536 [Default:CheckIn](INFO): Running loop #15 2022-05-19T18:13:56.536Z,1652984036.536 [Default:CheckIn] Running Loop=15 2022-05-19T18:13:56.536Z,1652984036.536 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:13:56.536Z,1652984036.536 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:13:58.539Z,1652984038.539 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181357.00,A,3648.12125,N,12147.23041,W,0.058,278.15,190522,,,D*70 2022-05-19T18:13:58.541Z,1652984038.541 [NAL9602](INFO): GPS fix at 20220519T181357: (36.802021, -121.787173) 2022-05-19T18:13:58.552Z,1652984038.552 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:13:58.552Z,1652984038.552 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:14:06.766Z,1652984046.766 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0021.lzma 2022-05-19T18:14:07.768Z,1652984047.768 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0021.lzma.bak 2022-05-19T18:14:07.768Z,1652984047.768 [DataOverHttps](INFO): SBD MOMSN=16809735 2022-05-19T18:14:11.469Z,1652984051.469 [NAL9602](INFO): SBD MO Status=0, MOMSN=19338, MT Status=0, MTMSN=0 2022-05-19T18:14:11.469Z,1652984051.469 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:14:23.954Z,1652984063.954 [DataOverHttps](INFO): Sending 128 bytes from file Logs/20220519T173103/Express0022.lzma 2022-05-19T18:14:24.956Z,1652984064.956 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0022.lzma.bak 2022-05-19T18:14:24.956Z,1652984064.956 [DataOverHttps](INFO): SBD MOMSN=16809738 2022-05-19T18:14:26.433Z,1652984066.433 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:14:26.434Z,1652984066.434 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:14:26.434Z,1652984066.434 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:14:42.175Z,1652984082.175 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:17:31.071Z,1652984251.071 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2022-05-19T18:19:27.024Z,1652984367.024 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:19:27.024Z,1652984367.024 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:19:27.024Z,1652984367.024 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:19:27.025Z,1652984367.025 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:19:27.415Z,1652984367.415 [Default:CheckIn:D] Stopped 2022-05-19T18:19:27.416Z,1652984367.416 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:19:27.813Z,1652984367.813 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.081486 min 2022-05-19T18:19:27.813Z,1652984367.813 [Default:CheckIn:E] Stopped 2022-05-19T18:19:27.814Z,1652984367.814 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:19:27.814Z,1652984367.814 [Default:CheckIn] Stopped 2022-05-19T18:19:27.814Z,1652984367.814 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:19:27.830Z,1652984367.830 [Default:CheckIn](INFO): Running loop #16 2022-05-19T18:19:27.830Z,1652984367.830 [Default:CheckIn] Running Loop=16 2022-05-19T18:19:27.830Z,1652984367.830 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:19:27.830Z,1652984367.830 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:19:29.829Z,1652984369.829 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,181929.00,A,3648.11960,N,12147.23387,W,0.078,323.71,190522,,,D*7F 2022-05-19T18:19:29.832Z,1652984369.832 [NAL9602](INFO): GPS fix at 20220519T181929: (36.801993, -121.787231) 2022-05-19T18:19:29.842Z,1652984369.842 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:19:29.842Z,1652984369.842 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:19:37.146Z,1652984377.146 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0024.lzma 2022-05-19T18:19:38.148Z,1652984378.148 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0024.lzma.bak 2022-05-19T18:19:38.149Z,1652984378.149 [DataOverHttps](INFO): SBD MOMSN=16809799 2022-05-19T18:19:39.937Z,1652984379.937 [NAL9602](INFO): SBD MO Status=0, MOMSN=19339, MT Status=0, MTMSN=0 2022-05-19T18:19:39.937Z,1652984379.937 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:19:54.454Z,1652984394.454 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0025.lzma 2022-05-19T18:19:55.456Z,1652984395.456 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0025.lzma.bak 2022-05-19T18:19:55.456Z,1652984395.456 [DataOverHttps](INFO): SBD MOMSN=16809802 2022-05-19T18:19:56.934Z,1652984396.934 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:19:56.934Z,1652984396.934 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:19:56.934Z,1652984396.934 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:20:10.635Z,1652984410.635 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:24:57.491Z,1652984697.491 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:24:57.491Z,1652984697.491 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:24:57.492Z,1652984697.492 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:24:57.492Z,1652984697.492 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:24:57.893Z,1652984697.893 [Default:CheckIn:D] Stopped 2022-05-19T18:24:57.893Z,1652984697.893 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:24:58.301Z,1652984698.301 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.589445 min 2022-05-19T18:24:58.301Z,1652984698.301 [Default:CheckIn:E] Stopped 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn] Stopped 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn](INFO): Running loop #17 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn] Running Loop=17 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:24:58.302Z,1652984698.302 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:25:00.309Z,1652984700.309 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,182459.00,A,3648.12394,N,12147.23154,W,0.039,323.71,190522,,,D*7D 2022-05-19T18:25:00.312Z,1652984700.312 [NAL9602](INFO): GPS fix at 20220519T182459: (36.802066, -121.787192) 2022-05-19T18:25:00.340Z,1652984700.340 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:25:00.340Z,1652984700.340 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:25:07.822Z,1652984707.822 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0027.lzma 2022-05-19T18:25:08.824Z,1652984708.824 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0027.lzma.bak 2022-05-19T18:25:08.824Z,1652984708.824 [DataOverHttps](INFO): SBD MOMSN=16809844 2022-05-19T18:25:18.081Z,1652984718.081 [NAL9602](INFO): SBD MO Status=0, MOMSN=19340, MT Status=0, MTMSN=0 2022-05-19T18:25:18.081Z,1652984718.081 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:25:25.266Z,1652984725.266 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0028.lzma 2022-05-19T18:25:26.268Z,1652984726.268 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0028.lzma.bak 2022-05-19T18:25:26.268Z,1652984726.268 [DataOverHttps](INFO): SBD MOMSN=16809847 2022-05-19T18:25:27.793Z,1652984727.793 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:25:27.793Z,1652984727.793 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:25:27.793Z,1652984727.793 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:25:48.787Z,1652984748.787 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:26:30.810Z,1652984790.810 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2022-05-19T18:26:30.812Z,1652984790.812 [BPC1](INFO): Received data from all battery sticks. 2022-05-19T18:30:28.401Z,1652985028.401 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:30:28.401Z,1652985028.401 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:30:28.401Z,1652985028.401 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:30:28.402Z,1652985028.402 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:30:28.833Z,1652985028.833 [Default:CheckIn:D] Stopped 2022-05-19T18:30:28.833Z,1652985028.833 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:30:29.196Z,1652985029.196 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.105103 min 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn:E] Stopped 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn] Stopped 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn](INFO): Running loop #18 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn] Running Loop=18 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:30:29.197Z,1652985029.197 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:30:31.209Z,1652985031.209 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183030.00,A,3648.11857,N,12147.23130,W,0.019,323.71,190522,,,D*70 2022-05-19T18:30:31.211Z,1652985031.211 [NAL9602](INFO): GPS fix at 20220519T183030: (36.801976, -121.787188) 2022-05-19T18:30:31.222Z,1652985031.222 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:30:31.222Z,1652985031.222 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:30:38.846Z,1652985038.846 [DataOverHttps](INFO): Sending 202 bytes from file Logs/20220519T173103/Courier0030.lzma 2022-05-19T18:30:39.844Z,1652985039.844 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0030.lzma.bak 2022-05-19T18:30:39.844Z,1652985039.844 [DataOverHttps](INFO): SBD MOMSN=16809914 2022-05-19T18:30:46.561Z,1652985046.561 [NAL9602](INFO): SBD MO Status=0, MOMSN=19341, MT Status=0, MTMSN=0 2022-05-19T18:30:46.561Z,1652985046.561 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:30:56.098Z,1652985056.098 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0031.lzma 2022-05-19T18:30:57.100Z,1652985057.100 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0031.lzma.bak 2022-05-19T18:30:57.100Z,1652985057.100 [DataOverHttps](INFO): SBD MOMSN=16809920 2022-05-19T18:30:58.302Z,1652985058.302 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:30:58.302Z,1652985058.302 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:30:58.302Z,1652985058.302 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:31:17.264Z,1652985077.264 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:35:58.908Z,1652985358.908 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:35:58.908Z,1652985358.908 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:35:58.909Z,1652985358.909 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:35:58.909Z,1652985358.909 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:35:59.299Z,1652985359.299 [Default:CheckIn:D] Stopped 2022-05-19T18:35:59.299Z,1652985359.299 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:35:59.709Z,1652985359.709 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.612882 min 2022-05-19T18:35:59.710Z,1652985359.710 [Default:CheckIn:E] Stopped 2022-05-19T18:35:59.710Z,1652985359.710 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:35:59.710Z,1652985359.710 [Default:CheckIn] Stopped 2022-05-19T18:35:59.714Z,1652985359.714 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:35:59.714Z,1652985359.714 [Default:CheckIn](INFO): Running loop #19 2022-05-19T18:35:59.714Z,1652985359.714 [Default:CheckIn] Running Loop=19 2022-05-19T18:35:59.715Z,1652985359.715 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:35:59.715Z,1652985359.715 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:36:01.709Z,1652985361.709 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,183600.00,A,3648.12086,N,12147.23538,W,0.097,323.71,190522,,,D*78 2022-05-19T18:36:01.712Z,1652985361.712 [NAL9602](INFO): GPS fix at 20220519T183600: (36.802014, -121.787256) 2022-05-19T18:36:01.739Z,1652985361.739 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:36:01.739Z,1652985361.739 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:36:09.522Z,1652985369.522 [DataOverHttps](INFO): Sending 70 bytes from file Logs/20220519T173103/Courier0033.lzma 2022-05-19T18:36:10.524Z,1652985370.524 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0033.lzma.bak 2022-05-19T18:36:10.525Z,1652985370.525 [DataOverHttps](INFO): SBD MOMSN=16809968 2022-05-19T18:36:27.030Z,1652985387.030 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0034.lzma 2022-05-19T18:36:28.032Z,1652985388.032 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0034.lzma.bak 2022-05-19T18:36:28.032Z,1652985388.032 [DataOverHttps](INFO): SBD MOMSN=16809981 2022-05-19T18:36:29.195Z,1652985389.195 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:36:29.195Z,1652985389.195 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:36:29.195Z,1652985389.195 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:36:31.633Z,1652985391.633 [NAL9602](INFO): SBD MO Status=0, MOMSN=19342, MT Status=0, MTMSN=0 2022-05-19T18:36:31.634Z,1652985391.634 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:37:02.303Z,1652985422.303 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:38:46.983Z,1652985526.983 [RDI_Pathfinder](ERROR): only read 2 of 4 data items 2022-05-19T18:41:29.809Z,1652985689.809 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:41:29.809Z,1652985689.809 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:41:29.809Z,1652985689.809 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:41:29.809Z,1652985689.809 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:41:30.213Z,1652985690.213 [Default:CheckIn:D] Stopped 2022-05-19T18:41:30.214Z,1652985690.214 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:41:30.625Z,1652985690.625 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.128117 min 2022-05-19T18:41:30.625Z,1652985690.625 [Default:CheckIn:E] Stopped 2022-05-19T18:41:30.625Z,1652985690.625 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:41:30.625Z,1652985690.625 [Default:CheckIn] Stopped 2022-05-19T18:41:30.625Z,1652985690.625 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:41:30.626Z,1652985690.626 [Default:CheckIn](INFO): Running loop #20 2022-05-19T18:41:30.626Z,1652985690.626 [Default:CheckIn] Running Loop=20 2022-05-19T18:41:30.626Z,1652985690.626 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:41:30.626Z,1652985690.626 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:41:32.633Z,1652985692.633 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184131.00,A,3648.11897,N,12147.23261,W,0.019,323.71,190522,,,D*7C 2022-05-19T18:41:32.636Z,1652985692.636 [NAL9602](INFO): GPS fix at 20220519T184131: (36.801983, -121.787210) 2022-05-19T18:41:32.674Z,1652985692.674 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:41:32.675Z,1652985692.675 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:41:40.362Z,1652985700.362 [DataOverHttps](INFO): Sending 74 bytes from file Logs/20220519T173103/Courier0036.lzma 2022-05-19T18:41:41.364Z,1652985701.364 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0036.lzma.bak 2022-05-19T18:41:41.364Z,1652985701.364 [DataOverHttps](INFO): SBD MOMSN=16810001 2022-05-19T18:41:45.957Z,1652985705.957 [NAL9602](INFO): SBD MO Status=0, MOMSN=19343, MT Status=0, MTMSN=0 2022-05-19T18:41:45.957Z,1652985705.957 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:41:57.846Z,1652985717.846 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20220519T173103/Express0037.lzma 2022-05-19T18:41:58.848Z,1652985718.848 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0037.lzma.bak 2022-05-19T18:41:58.848Z,1652985718.848 [DataOverHttps](INFO): SBD MOMSN=16810011 2022-05-19T18:42:00.115Z,1652985720.115 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:42:00.115Z,1652985720.115 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:42:00.115Z,1652985720.115 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:42:16.661Z,1652985736.661 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:47:00.735Z,1652986020.735 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:47:00.735Z,1652986020.735 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:47:00.735Z,1652986020.735 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:47:00.736Z,1652986020.736 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:47:01.123Z,1652986021.123 [Default:CheckIn:D] Stopped 2022-05-19T18:47:01.123Z,1652986021.123 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:47:01.497Z,1652986021.497 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.643270 min 2022-05-19T18:47:01.497Z,1652986021.497 [Default:CheckIn:E] Stopped 2022-05-19T18:47:01.497Z,1652986021.497 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn] Stopped 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn](INFO): Running loop #21 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn] Running Loop=21 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:47:01.498Z,1652986021.498 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:47:03.518Z,1652986023.518 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,184702.00,A,3648.14800,N,12147.25566,W,0.214,307.54,190522,,,D*79 2022-05-19T18:47:03.520Z,1652986023.520 [NAL9602](INFO): GPS fix at 20220519T184702: (36.802467, -121.787594) 2022-05-19T18:47:03.531Z,1652986023.531 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:47:03.531Z,1652986023.531 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:47:11.190Z,1652986031.190 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0039.lzma 2022-05-19T18:47:12.193Z,1652986032.193 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0039.lzma.bak 2022-05-19T18:47:12.193Z,1652986032.193 [DataOverHttps](INFO): SBD MOMSN=16810021 2022-05-19T18:47:21.688Z,1652986041.688 [NAL9602](INFO): SBD MO Status=0, MOMSN=19344, MT Status=0, MTMSN=0 2022-05-19T18:47:21.688Z,1652986041.688 [NAL9602](INFO): No messages in MT queue 2022-05-19T18:47:28.946Z,1652986048.946 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0040.lzma 2022-05-19T18:47:29.948Z,1652986049.948 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0040.lzma.bak 2022-05-19T18:47:29.948Z,1652986049.948 [DataOverHttps](INFO): SBD MOMSN=16810027 2022-05-19T18:47:31.398Z,1652986051.398 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:47:31.398Z,1652986051.398 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:47:31.398Z,1652986051.398 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:47:52.395Z,1652986072.395 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T18:52:31.965Z,1652986351.965 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:52:31.966Z,1652986351.966 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:52:31.966Z,1652986351.966 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:52:31.966Z,1652986351.966 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:52:32.375Z,1652986352.375 [Default:CheckIn:D] Stopped 2022-05-19T18:52:32.375Z,1652986352.375 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:52:32.800Z,1652986352.800 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.164144 min 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn:E] Stopped 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn] Stopped 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn](INFO): Running loop #22 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn] Running Loop=22 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:52:32.801Z,1652986352.801 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:52:34.783Z,1652986354.783 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185234.00,A,3648.17684,N,12147.28856,W,0.758,326.15,190522,,,A*74 2022-05-19T18:52:34.785Z,1652986354.785 [NAL9602](INFO): GPS fix at 20220519T185234: (36.802947, -121.788143) 2022-05-19T18:52:34.835Z,1652986354.835 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:52:34.835Z,1652986354.835 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:52:42.638Z,1652986362.638 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0042.lzma 2022-05-19T18:52:43.640Z,1652986363.640 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0042.lzma.bak 2022-05-19T18:52:43.640Z,1652986363.640 [DataOverHttps](INFO): SBD MOMSN=16810055 2022-05-19T18:53:00.234Z,1652986380.234 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220519T173103/Express0043.lzma 2022-05-19T18:53:01.236Z,1652986381.236 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0043.lzma.bak 2022-05-19T18:53:01.236Z,1652986381.236 [DataOverHttps](INFO): SBD MOMSN=16810061 2022-05-19T18:53:02.721Z,1652986382.721 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:53:02.721Z,1652986382.721 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:53:02.722Z,1652986382.722 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:57:32.960Z,1652986652.960 [RDI_Pathfinder](ERROR): only read 0 of 4 data items 2022-05-19T18:57:37.384Z,1652986657.384 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T18:58:03.249Z,1652986683.249 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T18:58:03.249Z,1652986683.249 [Default:CheckIn:C.Wait] Stopped 2022-05-19T18:58:03.249Z,1652986683.249 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T18:58:03.249Z,1652986683.249 [Default:CheckIn:D] Running Loop=1 2022-05-19T18:58:03.657Z,1652986683.657 [Default:CheckIn:D] Stopped 2022-05-19T18:58:03.657Z,1652986683.657 [Default:CheckIn:E] Running Loop=1 2022-05-19T18:58:04.061Z,1652986684.061 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 135.685514 min 2022-05-19T18:58:04.061Z,1652986684.061 [Default:CheckIn:E] Stopped 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn] Stopped 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn](INFO): Running loop #23 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn] Running Loop=23 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T18:58:04.062Z,1652986684.062 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T18:58:06.063Z,1652986686.063 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,185805.00,A,3648.17110,N,12147.28634,W,0.797,327.14,190522,,,A*7F 2022-05-19T18:58:06.065Z,1652986686.065 [NAL9602](INFO): GPS fix at 20220519T185805: (36.802852, -121.788106) 2022-05-19T18:58:06.076Z,1652986686.076 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T18:58:06.076Z,1652986686.076 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T18:58:13.962Z,1652986693.962 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0045.lzma 2022-05-19T18:58:14.964Z,1652986694.964 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0045.lzma.bak 2022-05-19T18:58:14.964Z,1652986694.964 [DataOverHttps](INFO): SBD MOMSN=16810100 2022-05-19T18:58:31.418Z,1652986711.418 [DataOverHttps](INFO): Sending 230 bytes from file Logs/20220519T173103/Express0046.lzma 2022-05-19T18:58:32.420Z,1652986712.420 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0046.lzma.bak 2022-05-19T18:58:32.421Z,1652986712.421 [DataOverHttps](INFO): SBD MOMSN=16810103 2022-05-19T18:58:33.553Z,1652986713.553 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T18:58:33.553Z,1652986713.553 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T18:58:33.553Z,1652986713.553 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T18:58:38.383Z,1652986718.383 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:03:34.125Z,1652987014.125 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:03:34.125Z,1652987014.125 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:03:34.126Z,1652987014.126 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:03:34.127Z,1652987014.127 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:03:34.538Z,1652987014.538 [Default:CheckIn:D] Stopped 2022-05-19T19:03:34.538Z,1652987014.538 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 141.200195 min 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn:E] Stopped 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn] Stopped 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn](INFO): Running loop #24 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn] Running Loop=24 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:03:34.960Z,1652987014.960 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:03:36.947Z,1652987016.947 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190336.00,A,3648.17022,N,12147.29163,W,0.467,327.14,190522,,,A*78 2022-05-19T19:03:36.949Z,1652987016.949 [NAL9602](INFO): GPS fix at 20220519T190336: (36.802837, -121.788194) 2022-05-19T19:03:36.979Z,1652987016.979 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:03:36.979Z,1652987016.979 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:03:45.030Z,1652987025.030 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220519T173103/Courier0048.lzma 2022-05-19T19:03:46.032Z,1652987026.032 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0048.lzma.bak 2022-05-19T19:03:46.032Z,1652987026.032 [DataOverHttps](INFO): SBD MOMSN=16810188 2022-05-19T19:04:02.414Z,1652987042.414 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0049.lzma 2022-05-19T19:04:03.416Z,1652987043.416 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0049.lzma.bak 2022-05-19T19:04:03.416Z,1652987043.416 [DataOverHttps](INFO): SBD MOMSN=16810192 2022-05-19T19:04:04.852Z,1652987044.852 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:04:04.852Z,1652987044.852 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:04:04.852Z,1652987044.852 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:04:07.652Z,1652987047.652 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-19T19:04:07.734Z,1652987047.734 [NAL9602](ERROR): received: +CSQ:0 OK344, 0, 0, 0, 0 OK 2022-05-19T19:07:48.239Z,1652987268.239 [NAL9602](INFO): SBD MO Status=2, MOMSN=19345, MT Status=2, MTMSN=0 2022-05-19T19:07:48.239Z,1652987268.239 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T19:07:51.058Z,1652987271.058 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2022-05-19T19:08:39.533Z,1652987319.533 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T19:09:05.409Z,1652987345.409 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:09:05.410Z,1652987345.410 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:09:05.410Z,1652987345.410 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:09:05.411Z,1652987345.411 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:09:05.809Z,1652987345.809 [Default:CheckIn:D] Stopped 2022-05-19T19:09:05.809Z,1652987345.809 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:09:06.214Z,1652987346.214 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 146.721387 min 2022-05-19T19:09:06.214Z,1652987346.214 [Default:CheckIn:E] Stopped 2022-05-19T19:09:06.214Z,1652987346.214 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn] Stopped 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn](INFO): Running loop #25 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn] Running Loop=25 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:09:06.215Z,1652987346.215 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:09:08.225Z,1652987348.225 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,190907.00,A,3648.17012,N,12147.28694,W,0.097,0.00,190522,,,A*75 2022-05-19T19:09:08.228Z,1652987348.228 [NAL9602](INFO): GPS fix at 20220519T190907: (36.802835, -121.788116) 2022-05-19T19:09:08.255Z,1652987348.255 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:09:08.255Z,1652987348.255 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:09:16.210Z,1652987356.210 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0051.lzma 2022-05-19T19:09:17.212Z,1652987357.212 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0051.lzma.bak 2022-05-19T19:09:17.212Z,1652987357.212 [DataOverHttps](INFO): SBD MOMSN=16810265 2022-05-19T19:09:33.639Z,1652987373.639 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220519T173103/Express0052.lzma 2022-05-19T19:09:34.640Z,1652987374.640 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0052.lzma.bak 2022-05-19T19:09:34.640Z,1652987374.640 [DataOverHttps](INFO): SBD MOMSN=16810268 2022-05-19T19:09:36.129Z,1652987376.129 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:09:36.130Z,1652987376.130 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:09:36.130Z,1652987376.130 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:09:40.539Z,1652987380.539 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:14:36.730Z,1652987676.730 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:14:36.734Z,1652987676.734 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:14:36.735Z,1652987676.735 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:14:36.735Z,1652987676.735 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:14:37.110Z,1652987677.110 [Default:CheckIn:D] Stopped 2022-05-19T19:14:37.110Z,1652987677.110 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 152.243050 min 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn:E] Stopped 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn] Stopped 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn](INFO): Running loop #26 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn] Running Loop=26 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:14:37.508Z,1652987677.508 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:14:39.501Z,1652987679.501 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,191438.00,A,3648.17280,N,12147.28634,W,1.030,0.00,190522,,,A*7A 2022-05-19T19:14:39.503Z,1652987679.503 [NAL9602](INFO): GPS fix at 20220519T191438: (36.802880, -121.788106) 2022-05-19T19:14:39.519Z,1652987679.519 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:14:39.519Z,1652987679.519 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:14:47.450Z,1652987687.450 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0054.lzma 2022-05-19T19:14:48.452Z,1652987688.452 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0054.lzma.bak 2022-05-19T19:14:48.452Z,1652987688.452 [DataOverHttps](INFO): SBD MOMSN=16810279 2022-05-19T19:15:05.046Z,1652987705.046 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0055.lzma 2022-05-19T19:15:06.048Z,1652987706.048 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0055.lzma.bak 2022-05-19T19:15:06.048Z,1652987706.048 [DataOverHttps](INFO): SBD MOMSN=16810282 2022-05-19T19:15:07.391Z,1652987707.391 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:15:07.391Z,1652987707.391 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:15:07.391Z,1652987707.391 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:15:10.204Z,1652987710.204 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-19T19:15:10.286Z,1652987710.286 [NAL9602](ERROR): received: +CSQ:0 OK345, 2, 0, 0, 0 OK 2022-05-19T19:15:38.899Z,1652987738.899 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for BIT error 2022-05-19T19:19:41.292Z,1652987981.292 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T19:20:07.972Z,1652988007.972 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:20:07.973Z,1652988007.973 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:20:07.973Z,1652988007.973 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:20:07.973Z,1652988007.973 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:20:08.369Z,1652988008.369 [Default:CheckIn:D] Stopped 2022-05-19T19:20:08.369Z,1652988008.369 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 157.764046 min 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn:E] Stopped 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn] Stopped 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:20:08.789Z,1652988008.789 [Default:CheckIn](INFO): Running loop #27 2022-05-19T19:20:08.790Z,1652988008.790 [Default:CheckIn] Running Loop=27 2022-05-19T19:20:08.790Z,1652988008.790 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:20:08.790Z,1652988008.790 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:20:10.791Z,1652988010.791 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192010.00,A,3648.17322,N,12147.28902,W,1.905,135.05,190522,,,A*79 2022-05-19T19:20:10.793Z,1652988010.793 [NAL9602](INFO): GPS fix at 20220519T192010: (36.802887, -121.788150) 2022-05-19T19:20:10.830Z,1652988010.830 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:20:10.830Z,1652988010.830 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:20:18.786Z,1652988018.786 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0057.lzma 2022-05-19T19:20:19.788Z,1652988019.788 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0057.lzma.bak 2022-05-19T19:20:19.788Z,1652988019.788 [DataOverHttps](INFO): SBD MOMSN=16810318 2022-05-19T19:20:36.374Z,1652988036.374 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20220519T173103/Express0058.lzma 2022-05-19T19:20:37.376Z,1652988037.376 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0058.lzma.bak 2022-05-19T19:20:37.376Z,1652988037.376 [DataOverHttps](INFO): SBD MOMSN=16810321 2022-05-19T19:20:38.738Z,1652988038.738 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:20:38.739Z,1652988038.739 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:20:38.739Z,1652988038.739 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:20:43.503Z,1652988043.503 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:25:39.249Z,1652988339.249 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:25:39.249Z,1652988339.249 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:25:39.249Z,1652988339.249 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:25:39.249Z,1652988339.249 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:25:39.657Z,1652988339.657 [Default:CheckIn:D] Stopped 2022-05-19T19:25:39.657Z,1652988339.657 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:25:40.047Z,1652988340.047 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 163.285514 min 2022-05-19T19:25:40.047Z,1652988340.047 [Default:CheckIn:E] Stopped 2022-05-19T19:25:40.047Z,1652988340.047 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn] Stopped 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn](INFO): Running loop #28 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn] Running Loop=28 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:25:40.048Z,1652988340.048 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:25:42.065Z,1652988342.065 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,192541.00,A,3648.16655,N,12147.27705,W,1.011,0.00,190522,,,A*74 2022-05-19T19:25:42.068Z,1652988342.068 [NAL9602](INFO): GPS fix at 20220519T192541: (36.802776, -121.787951) 2022-05-19T19:25:42.079Z,1652988342.079 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:25:42.079Z,1652988342.079 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:25:50.098Z,1652988350.098 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0060.lzma 2022-05-19T19:25:51.100Z,1652988351.100 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0060.lzma.bak 2022-05-19T19:25:51.100Z,1652988351.100 [DataOverHttps](INFO): SBD MOMSN=16810338 2022-05-19T19:26:07.450Z,1652988367.450 [DataOverHttps](INFO): Sending 129 bytes from file Logs/20220519T173103/Express0061.lzma 2022-05-19T19:26:08.452Z,1652988368.452 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0061.lzma.bak 2022-05-19T19:26:08.452Z,1652988368.452 [DataOverHttps](INFO): SBD MOMSN=16810341 2022-05-19T19:26:09.950Z,1652988369.950 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:26:09.950Z,1652988369.950 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:26:09.950Z,1652988369.950 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:26:12.772Z,1652988372.772 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-19T19:26:12.854Z,1652988372.854 [NAL9602](ERROR): received: +CSQ:1 OK345, 2, 0, 0, 0 OK 2022-05-19T19:28:26.897Z,1652988506.897 [NAL9602](INFO): SBD MO Status=2, MOMSN=19345, MT Status=2, MTMSN=0 2022-05-19T19:28:26.897Z,1652988506.897 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T19:29:53.353Z,1652988593.353 [NAL9602](INFO): SBD MO Status=2, MOMSN=19345, MT Status=2, MTMSN=0 2022-05-19T19:29:53.353Z,1652988593.353 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T19:30:44.255Z,1652988644.255 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T19:31:10.520Z,1652988670.520 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:31:10.520Z,1652988670.520 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:31:10.520Z,1652988670.520 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:31:10.521Z,1652988670.521 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:31:10.953Z,1652988670.953 [Default:CheckIn:D] Stopped 2022-05-19T19:31:10.953Z,1652988670.953 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:31:11.342Z,1652988671.342 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 168.807113 min 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn:E] Stopped 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn] Stopped 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn](INFO): Running loop #29 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn] Running Loop=29 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:31:11.343Z,1652988671.343 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:31:13.345Z,1652988673.345 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193112.00,A,3648.17065,N,12147.28653,W,0.447,348.91,190522,,,A*7F 2022-05-19T19:31:13.347Z,1652988673.347 [NAL9602](INFO): GPS fix at 20220519T193112: (36.802844, -121.788109) 2022-05-19T19:31:13.358Z,1652988673.358 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:31:13.378Z,1652988673.378 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:31:21.266Z,1652988681.266 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220519T173103/Courier0063.lzma 2022-05-19T19:31:22.268Z,1652988682.268 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0063.lzma.bak 2022-05-19T19:31:22.268Z,1652988682.268 [DataOverHttps](INFO): SBD MOMSN=16810356 2022-05-19T19:31:38.906Z,1652988698.906 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220519T173103/Express0064.lzma 2022-05-19T19:31:39.908Z,1652988699.908 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0064.lzma.bak 2022-05-19T19:31:39.908Z,1652988699.908 [DataOverHttps](INFO): SBD MOMSN=16810359 2022-05-19T19:31:41.254Z,1652988701.254 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:31:41.258Z,1652988701.258 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:31:41.258Z,1652988701.258 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:31:45.255Z,1652988705.255 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:33:57.369Z,1652988837.369 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2022-05-19T19:33:57.371Z,1652988837.371 [BPC1](INFO): Received data from all battery sticks. 2022-05-19T19:36:41.810Z,1652989001.810 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:36:41.810Z,1652989001.810 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:36:41.810Z,1652989001.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:36:41.811Z,1652989001.811 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:36:42.227Z,1652989002.227 [Default:CheckIn:D] Stopped 2022-05-19T19:36:42.227Z,1652989002.227 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:36:42.615Z,1652989002.615 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 174.328353 min 2022-05-19T19:36:42.615Z,1652989002.615 [Default:CheckIn:E] Stopped 2022-05-19T19:36:42.615Z,1652989002.615 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:36:42.615Z,1652989002.615 [Default:CheckIn] Stopped 2022-05-19T19:36:42.616Z,1652989002.616 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:36:42.616Z,1652989002.616 [Default:CheckIn](INFO): Running loop #30 2022-05-19T19:36:42.616Z,1652989002.616 [Default:CheckIn] Running Loop=30 2022-05-19T19:36:42.616Z,1652989002.616 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:36:42.616Z,1652989002.616 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:36:44.629Z,1652989004.629 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,193643.00,A,3648.17068,N,12147.28685,W,1.827,121.22,190522,,,A*74 2022-05-19T19:36:44.631Z,1652989004.631 [NAL9602](INFO): GPS fix at 20220519T193643: (36.802845, -121.788114) 2022-05-19T19:36:44.643Z,1652989004.643 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:36:44.643Z,1652989004.643 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:36:53.550Z,1652989013.550 [DataOverHttps](INFO): Sending 83 bytes from file Logs/20220519T173103/Courier0066.lzma 2022-05-19T19:36:54.552Z,1652989014.552 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0066.lzma.bak 2022-05-19T19:36:54.552Z,1652989014.552 [DataOverHttps](INFO): SBD MOMSN=16810454 2022-05-19T19:37:11.018Z,1652989031.018 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20220519T173103/Express0067.lzma 2022-05-19T19:37:12.020Z,1652989032.020 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0067.lzma.bak 2022-05-19T19:37:12.020Z,1652989032.020 [DataOverHttps](INFO): SBD MOMSN=16810459 2022-05-19T19:37:13.347Z,1652989033.347 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:37:13.347Z,1652989033.347 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:37:13.347Z,1652989033.347 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:41:47.216Z,1652989307.216 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T19:42:13.893Z,1652989333.893 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:42:13.893Z,1652989333.893 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:42:13.893Z,1652989333.893 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:42:13.893Z,1652989333.893 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:42:14.297Z,1652989334.297 [Default:CheckIn:D] Stopped 2022-05-19T19:42:14.297Z,1652989334.297 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:42:14.753Z,1652989334.753 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 179.862842 min 2022-05-19T19:42:14.753Z,1652989334.753 [Default:CheckIn:E] Stopped 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn] Stopped 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn](INFO): Running loop #31 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn] Running Loop=31 2022-05-19T19:42:14.754Z,1652989334.754 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:42:14.755Z,1652989334.755 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:42:16.736Z,1652989336.736 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194216.00,A,3648.18485,N,12147.31389,W,1.575,317.41,190522,,,A*76 2022-05-19T19:42:16.739Z,1652989336.739 [NAL9602](INFO): GPS fix at 20220519T194216: (36.803081, -121.788565) 2022-05-19T19:42:16.802Z,1652989336.802 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:42:16.802Z,1652989336.802 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:42:24.708Z,1652989344.708 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220519T173103/Courier0069.lzma 2022-05-19T19:42:25.705Z,1652989345.705 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0069.lzma.bak 2022-05-19T19:42:25.705Z,1652989345.705 [DataOverHttps](INFO): SBD MOMSN=16810477 2022-05-19T19:42:41.918Z,1652989361.918 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220519T173103/Express0070.lzma 2022-05-19T19:42:42.920Z,1652989362.920 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0070.lzma.bak 2022-05-19T19:42:42.920Z,1652989362.920 [DataOverHttps](INFO): SBD MOMSN=16810481 2022-05-19T19:42:44.215Z,1652989364.215 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:42:44.215Z,1652989364.215 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:42:44.215Z,1652989364.215 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:42:49.431Z,1652989369.431 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:47:44.783Z,1652989664.783 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:47:44.783Z,1652989664.783 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:47:44.783Z,1652989664.783 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:47:44.783Z,1652989664.783 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:47:45.178Z,1652989665.178 [Default:CheckIn:D] Stopped 2022-05-19T19:47:45.178Z,1652989665.178 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:47:45.574Z,1652989665.574 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 185.377523 min 2022-05-19T19:47:45.574Z,1652989665.574 [Default:CheckIn:E] Stopped 2022-05-19T19:47:45.574Z,1652989665.574 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:47:45.574Z,1652989665.574 [Default:CheckIn] Stopped 2022-05-19T19:47:45.590Z,1652989665.590 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:47:45.590Z,1652989665.590 [Default:CheckIn](INFO): Running loop #32 2022-05-19T19:47:45.590Z,1652989665.590 [Default:CheckIn] Running Loop=32 2022-05-19T19:47:45.591Z,1652989665.591 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:47:45.591Z,1652989665.591 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:47:47.586Z,1652989667.586 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,194746.00,A,3648.16793,N,12147.28005,W,0.097,114.63,190522,,,A*7A 2022-05-19T19:47:47.588Z,1652989667.588 [NAL9602](INFO): GPS fix at 20220519T194746: (36.802799, -121.788001) 2022-05-19T19:47:47.603Z,1652989667.603 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:47:47.603Z,1652989667.603 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:47:55.398Z,1652989675.398 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0072.lzma 2022-05-19T19:47:56.400Z,1652989676.400 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0072.lzma.bak 2022-05-19T19:47:56.400Z,1652989676.400 [DataOverHttps](INFO): SBD MOMSN=16810494 2022-05-19T19:48:12.626Z,1652989692.626 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20220519T173103/Express0073.lzma 2022-05-19T19:48:13.628Z,1652989693.628 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0073.lzma.bak 2022-05-19T19:48:13.628Z,1652989693.628 [DataOverHttps](INFO): SBD MOMSN=16810497 2022-05-19T19:48:15.100Z,1652989695.100 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:48:15.100Z,1652989695.100 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:48:15.100Z,1652989695.100 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:49:20.908Z,1652989760.908 [NAL9602](INFO): SBD MO Status=2, MOMSN=19345, MT Status=2, MTMSN=0 2022-05-19T19:49:20.908Z,1652989760.908 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2022-05-19T19:52:49.375Z,1652989969.375 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T19:53:15.646Z,1652989995.646 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:53:15.646Z,1652989995.646 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:53:15.646Z,1652989995.646 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:53:15.647Z,1652989995.647 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:53:16.044Z,1652989996.044 [Default:CheckIn:D] Stopped 2022-05-19T19:53:16.045Z,1652989996.045 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 190.891976 min 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn:E] Stopped 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn] Stopped 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:53:16.454Z,1652989996.454 [Default:CheckIn](INFO): Running loop #33 2022-05-19T19:53:16.455Z,1652989996.455 [Default:CheckIn] Running Loop=33 2022-05-19T19:53:16.455Z,1652989996.455 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:53:16.455Z,1652989996.455 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:53:18.461Z,1652989998.461 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195317.00,A,3648.16628,N,12147.27905,W,0.097,114.63,190522,,,A*7C 2022-05-19T19:53:18.463Z,1652989998.463 [NAL9602](INFO): GPS fix at 20220519T195317: (36.802771, -121.787984) 2022-05-19T19:53:18.500Z,1652989998.500 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:53:18.500Z,1652989998.500 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:53:25.834Z,1652990005.834 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0075.lzma 2022-05-19T19:53:26.836Z,1652990006.836 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0075.lzma.bak 2022-05-19T19:53:26.836Z,1652990006.836 [DataOverHttps](INFO): SBD MOMSN=16810514 2022-05-19T19:53:43.059Z,1652990023.059 [DataOverHttps](INFO): Sending 208 bytes from file Logs/20220519T173103/Express0076.lzma 2022-05-19T19:53:44.060Z,1652990024.060 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0076.lzma.bak 2022-05-19T19:53:44.060Z,1652990024.060 [DataOverHttps](INFO): SBD MOMSN=16810517 2022-05-19T19:53:45.549Z,1652990025.549 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:53:45.550Z,1652990025.550 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:53:45.550Z,1652990025.550 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:53:50.388Z,1652990030.388 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T19:54:58.732Z,1652990098.732 [DropWeight](CRITICAL): DROP WEIGHT MISSING. 2022-05-19T19:54:58.732Z,1652990098.732 [DropWeight] Hardware Fault, FailCount= 1 2022-05-19T19:54:58.733Z,1652990098.733 [DropWeight](ERROR): Hardware Fault 2022-05-19T19:54:58.849Z,1652990098.849 [CommandExec](FAULT): Scheduling is paused 2022-05-19T19:54:58.849Z,1652990098.849 [CBIT](INFO): Critical error at 20220519T195458 2022-05-19T19:54:58.859Z,1652990098.859 [CBIT](ERROR): Hardware Fault in component: DropWeight 2022-05-19T19:54:58.860Z,1652990098.860 [CBIT](CRITICAL): Hardware Fault in component: DropWeight 2022-05-19T19:54:59.122Z,1652990099.122 [CBIT](INFO): Critical error at 20220519T195458 2022-05-19T19:58:46.153Z,1652990326.153 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T19:58:46.153Z,1652990326.153 [Default:CheckIn:C.Wait] Stopped 2022-05-19T19:58:46.153Z,1652990326.153 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T19:58:46.154Z,1652990326.154 [Default:CheckIn:D] Running Loop=1 2022-05-19T19:58:46.546Z,1652990326.546 [Default:CheckIn:D] Stopped 2022-05-19T19:58:46.546Z,1652990326.546 [Default:CheckIn:E] Running Loop=1 2022-05-19T19:58:46.985Z,1652990326.985 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 196.400326 min 2022-05-19T19:58:46.986Z,1652990326.986 [Default:CheckIn:E] Stopped 2022-05-19T19:58:46.986Z,1652990326.986 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T19:58:46.986Z,1652990326.986 [Default:CheckIn] Stopped 2022-05-19T19:58:46.990Z,1652990326.990 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T19:58:46.990Z,1652990326.990 [Default:CheckIn](INFO): Running loop #34 2022-05-19T19:58:46.990Z,1652990326.990 [Default:CheckIn] Running Loop=34 2022-05-19T19:58:46.991Z,1652990326.991 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T19:58:46.991Z,1652990326.991 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T19:58:48.963Z,1652990328.963 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,195848.00,A,3648.16358,N,12147.27855,W,0.039,0.00,190522,,,A*7E 2022-05-19T19:58:48.965Z,1652990328.965 [NAL9602](INFO): GPS fix at 20220519T195848: (36.802726, -121.787976) 2022-05-19T19:58:48.999Z,1652990328.999 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T19:58:48.999Z,1652990328.999 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T19:58:57.010Z,1652990337.010 [DataOverHttps](INFO): Sending 181 bytes from file Logs/20220519T173103/Courier0078.lzma 2022-05-19T19:58:58.012Z,1652990338.012 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0078.lzma.bak 2022-05-19T19:58:58.012Z,1652990338.012 [DataOverHttps](INFO): SBD MOMSN=16810579 2022-05-19T19:59:14.334Z,1652990354.334 [DataOverHttps](INFO): Sending 157 bytes from file Logs/20220519T173103/Express0079.lzma 2022-05-19T19:59:15.337Z,1652990355.337 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0079.lzma.bak 2022-05-19T19:59:15.337Z,1652990355.337 [DataOverHttps](INFO): SBD MOMSN=16810585 2022-05-19T19:59:16.880Z,1652990356.880 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T19:59:16.880Z,1652990356.880 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T19:59:16.880Z,1652990356.880 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T19:59:19.663Z,1652990359.663 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-19T19:59:19.746Z,1652990359.746 [NAL9602](ERROR): received: +CSQ:0 OK345, 2, 0, 0, 0 OK 2022-05-19T20:03:51.555Z,1652990631.555 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T20:04:17.429Z,1652990657.429 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T20:04:17.429Z,1652990657.429 [Default:CheckIn:C.Wait] Stopped 2022-05-19T20:04:17.429Z,1652990657.429 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T20:04:17.429Z,1652990657.429 [Default:CheckIn:D] Running Loop=1 2022-05-19T20:04:17.827Z,1652990657.827 [Default:CheckIn:D] Stopped 2022-05-19T20:04:17.827Z,1652990657.827 [Default:CheckIn:E] Running Loop=1 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 201.921680 min 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn:E] Stopped 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn] Stopped 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn](INFO): Running loop #35 2022-05-19T20:04:18.230Z,1652990658.230 [Default:CheckIn] Running Loop=35 2022-05-19T20:04:18.231Z,1652990658.231 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T20:04:18.231Z,1652990658.231 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T20:04:20.243Z,1652990660.243 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200419.00,A,3648.16833,N,12147.28005,W,0.486,0.00,190522,,,A*7D 2022-05-19T20:04:20.245Z,1652990660.245 [NAL9602](INFO): GPS fix at 20220519T200419: (36.802805, -121.788001) 2022-05-19T20:04:20.256Z,1652990660.256 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T20:04:20.256Z,1652990660.256 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T20:04:27.534Z,1652990667.534 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0081.lzma 2022-05-19T20:04:28.536Z,1652990668.536 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0081.lzma.bak 2022-05-19T20:04:28.536Z,1652990668.536 [DataOverHttps](INFO): SBD MOMSN=16810630 2022-05-19T20:04:44.798Z,1652990684.798 [DataOverHttps](INFO): Sending 205 bytes from file Logs/20220519T173103/Express0082.lzma 2022-05-19T20:04:45.800Z,1652990685.800 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0082.lzma.bak 2022-05-19T20:04:45.801Z,1652990685.801 [DataOverHttps](INFO): SBD MOMSN=16810635 2022-05-19T20:04:47.318Z,1652990687.318 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T20:04:47.318Z,1652990687.318 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T20:04:47.318Z,1652990687.318 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T20:04:52.555Z,1652990692.555 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T20:07:07.103Z,1652990827.103 [RDI_Pathfinder](ERROR): only read 0 of 1 data item for water mass range. 2022-05-19T20:09:47.888Z,1652990987.888 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T20:09:47.888Z,1652990987.888 [Default:CheckIn:C.Wait] Stopped 2022-05-19T20:09:47.888Z,1652990987.888 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T20:09:47.888Z,1652990987.888 [Default:CheckIn:D] Running Loop=1 2022-05-19T20:09:48.301Z,1652990988.301 [Default:CheckIn:D] Stopped 2022-05-19T20:09:48.301Z,1652990988.301 [Default:CheckIn:E] Running Loop=1 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 207.429574 min 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn:E] Stopped 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn] Stopped 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn](INFO): Running loop #36 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn] Running Loop=36 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T20:09:48.740Z,1652990988.740 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T20:09:50.742Z,1652990990.742 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200950.00,A,3648.16503,N,12147.28075,W,0.525,256.32,190522,,,A*7C 2022-05-19T20:09:50.744Z,1652990990.744 [NAL9602](INFO): GPS fix at 20220519T200950: (36.802751, -121.788012) 2022-05-19T20:09:50.775Z,1652990990.775 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T20:09:50.775Z,1652990990.775 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T20:09:58.254Z,1652990998.254 [DataOverHttps](INFO): Sending 73 bytes from file Logs/20220519T173103/Courier0084.lzma 2022-05-19T20:09:59.009Z,1652990999.009 [CBIT](INFO): Clearing failed state for component DropWeight 2022-05-19T20:09:59.009Z,1652990999.009 [DropWeight] No Fault, FailCount= 1 2022-05-19T20:09:59.256Z,1652990999.256 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0084.lzma.bak 2022-05-19T20:09:59.256Z,1652990999.256 [DataOverHttps](INFO): SBD MOMSN=16810679 2022-05-19T20:10:15.606Z,1652991015.606 [DataOverHttps](INFO): Sending 130 bytes from file Logs/20220519T173103/Express0085.lzma 2022-05-19T20:10:16.608Z,1652991016.608 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0085.lzma.bak 2022-05-19T20:10:16.609Z,1652991016.609 [DataOverHttps](INFO): SBD MOMSN=16810684 2022-05-19T20:10:17.808Z,1652991017.808 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T20:10:17.808Z,1652991017.808 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T20:10:17.808Z,1652991017.808 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T20:10:21.416Z,1652991021.416 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2022-05-19T20:10:21.490Z,1652991021.490 [NAL9602](ERROR): received: +CSQ:0 OK345, 2, 0, 0, 0 OK 2022-05-19T20:14:53.313Z,1652991293.313 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2022-05-19T20:15:18.368Z,1652991318.368 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T20:15:18.368Z,1652991318.368 [Default:CheckIn:C.Wait] Stopped 2022-05-19T20:15:18.368Z,1652991318.368 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T20:15:18.369Z,1652991318.369 [Default:CheckIn:D] Running Loop=1 2022-05-19T20:15:18.789Z,1652991318.789 [Default:CheckIn:D] Stopped 2022-05-19T20:15:18.789Z,1652991318.789 [Default:CheckIn:E] Running Loop=1 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 212.937712 min 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn:E] Stopped 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn] Stopped 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn](INFO): Running loop #37 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn] Running Loop=37 2022-05-19T20:15:19.181Z,1652991319.181 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T20:15:19.182Z,1652991319.182 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T20:15:21.185Z,1652991321.185 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201520.00,A,3648.14793,N,12147.25380,W,1.788,170.17,190522,,,A*7F 2022-05-19T20:15:21.187Z,1652991321.187 [NAL9602](INFO): GPS fix at 20220519T201520: (36.802465, -121.787563) 2022-05-19T20:15:21.197Z,1652991321.197 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T20:15:21.197Z,1652991321.197 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T20:15:29.214Z,1652991329.214 [DataOverHttps](INFO): Sending 72 bytes from file Logs/20220519T173103/Courier0087.lzma 2022-05-19T20:15:30.216Z,1652991330.216 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Courier0087.lzma.bak 2022-05-19T20:15:30.216Z,1652991330.216 [DataOverHttps](INFO): SBD MOMSN=16810700 2022-05-19T20:15:46.746Z,1652991346.746 [DataOverHttps](INFO): Sending 206 bytes from file Logs/20220519T173103/Express0088.lzma 2022-05-19T20:15:47.748Z,1652991347.748 [DataOverHttps](INFO): Moved sent file to Logs/20220519T173103/Express0088.lzma.bak 2022-05-19T20:15:47.748Z,1652991347.748 [DataOverHttps](INFO): SBD MOMSN=16810705 2022-05-19T20:15:49.101Z,1652991349.101 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T20:15:49.101Z,1652991349.101 [Default:CheckIn:C.Wait] Running Loop=1 2022-05-19T20:15:49.101Z,1652991349.101 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2022-05-19T20:15:53.503Z,1652991353.503 [NAL9602](INFO): Not Powering down - fast GPS 2022-05-19T20:16:56.959Z,1652991416.959 [RDI_Pathfinder](ERROR): only read 1 of 4 data items 2022-05-19T20:18:44.704Z,1652991524.704 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.256142 2022-05-19T20:18:58.499Z,1652991538.499 [DataOverHttps](INFO): setting available, lastComms_.elapsed()=0.003427 2022-05-19T20:19:59.403Z,1652991599.403 [DataOverHttps](INFO): setting unavailable, lastComms_.elapsed()=60.907402 2022-05-19T20:20:49.643Z,1652991649.643 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2022-05-19T20:20:49.643Z,1652991649.643 [Default:CheckIn:C.Wait] Stopped 2022-05-19T20:20:49.643Z,1652991649.643 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2022-05-19T20:20:49.643Z,1652991649.643 [Default:CheckIn:D] Running Loop=1 2022-05-19T20:20:50.063Z,1652991650.063 [Default:CheckIn:D] Stopped 2022-05-19T20:20:50.063Z,1652991650.063 [Default:CheckIn:E] Running Loop=1 2022-05-19T20:20:50.456Z,1652991650.456 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 218.458919 min 2022-05-19T20:20:50.456Z,1652991650.456 [Default:CheckIn:E] Stopped 2022-05-19T20:20:50.456Z,1652991650.456 [Default:CheckIn](INFO): Completed Default:CheckIn 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn] Stopped 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn](INFO): Running loop #38 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn] Running Loop=38 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2022-05-19T20:20:50.457Z,1652991650.457 [Default:CheckIn:Read_GPS] Running Loop=1 2022-05-19T20:20:52.465Z,1652991652.465 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202051.00,A,3648.16016,N,12147.29752,W,1.244,275.83,190522,,,A*7E 2022-05-19T20:20:52.467Z,1652991652.467 [NAL9602](INFO): GPS fix at 20220519T202051: (36.802669, -121.788292) 2022-05-19T20:20:52.478Z,1652991652.478 [Default:CheckIn:Read_GPS] Stopped 2022-05-19T20:20:52.478Z,1652991652.478 [Default:CheckIn:Read_Iridium] Running Loop=1 2022-05-19T20:21:03.667Z,1652991663.667 [DataOverHttps](INFO): Exceeded connect timeout, disconnecting. 2022-05-19T20:21:13.928Z,1652991673.928 [CommandExec](IMPORTANT): got command quit 2022-05-19T20:21:14.930Z,1652991674.930 [CommandExec ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:14.931Z,1652991674.931 [CommandExec](INFO): Uninitializing the command executive. 2022-05-19T20:21:14.931Z,1652991674.931 [CommandExec](INFO): Uninitializing the command scheduler. 2022-05-19T20:21:14.931Z,1652991674.931 [CommandExec ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.014Z,1652991675.014 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2022-05-19T20:21:15.014Z,1652991675.014 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2022-05-19T20:21:15.014Z,1652991675.014 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.015Z,1652991675.015 [NavChartDb](INFO): Join timeout helper Thread ID is 5814 2022-05-19T20:21:15.350Z,1652991675.350 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:15.351Z,1652991675.351 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.358Z,1652991675.358 [ComponentRegistry](INFO): Shutting down WetLabsUBAT ThreadHandler 2022-05-19T20:21:15.358Z,1652991675.358 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.359Z,1652991675.359 [WetLabsUBAT](INFO): Join timeout helper Thread ID is 5815 2022-05-19T20:21:15.366Z,1652991675.366 [WetLabsUBAT ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:15.367Z,1652991675.367 [WetLabsUBAT](INFO): Powering down 2022-05-19T20:21:15.367Z,1652991675.367 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.378Z,1652991675.378 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2022-05-19T20:21:15.378Z,1652991675.378 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.379Z,1652991675.379 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 5816 2022-05-19T20:21:15.422Z,1652991675.422 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:15.423Z,1652991675.423 [WetLabsBB2FL](INFO): Powering down 2022-05-19T20:21:15.423Z,1652991675.423 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.442Z,1652991675.442 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2022-05-19T20:21:15.442Z,1652991675.442 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.443Z,1652991675.443 [CTD_Seabird](INFO): Join timeout helper Thread ID is 5817 2022-05-19T20:21:15.738Z,1652991675.738 [CTD_Seabird](INFO): Powering down 2022-05-19T20:21:15.750Z,1652991675.750 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:15.750Z,1652991675.750 [CTD_Seabird](INFO): Powering down 2022-05-19T20:21:15.762Z,1652991675.762 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.766Z,1652991675.766 [ComponentRegistry](INFO): Shutting down DAT ThreadHandler 2022-05-19T20:21:15.766Z,1652991675.766 [DAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.767Z,1652991675.767 [DAT](INFO): Join timeout helper Thread ID is 5818 2022-05-19T20:21:15.799Z,1652991675.799 [DAT](INFO): Powering down 2022-05-19T20:21:15.875Z,1652991675.875 [DAT ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:15.875Z,1652991675.875 [DAT](INFO): Powering down 2022-05-19T20:21:15.876Z,1652991675.876 [DAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.904Z,1652991675.904 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2022-05-19T20:21:15.904Z,1652991675.904 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:15.904Z,1652991675.904 [Radio_Surface](INFO): Join timeout helper Thread ID is 5819 2022-05-19T20:21:16.079Z,1652991676.079 [Radio_Surface](INFO): Powering down 2022-05-19T20:21:16.079Z,1652991676.079 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:16.080Z,1652991676.080 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:16.099Z,1652991676.099 [ComponentRegistry](INFO): Shutting down Onboard ThreadHandler 2022-05-19T20:21:16.099Z,1652991676.099 [Onboard ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:16.099Z,1652991676.099 [Onboard](INFO): Join timeout helper Thread ID is 5820 2022-05-19T20:21:16.926Z,1652991676.926 [Onboard ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:16.927Z,1652991676.927 [Onboard ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:16.944Z,1652991676.944 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2022-05-19T20:21:16.944Z,1652991676.944 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:16.944Z,1652991676.944 [DataOverHttps](INFO): Join timeout helper Thread ID is 5821 2022-05-19T20:21:17.722Z,1652991677.722 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:17.723Z,1652991677.723 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.735Z,1652991677.735 [ComponentRegistry](INFO): Shutting down BackseatComponent ThreadHandler 2022-05-19T20:21:17.735Z,1652991677.735 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.735Z,1652991677.735 [BackseatComponent](INFO): Join timeout helper Thread ID is 5822 2022-05-19T20:21:17.874Z,1652991677.874 [BackseatComponent ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:17.875Z,1652991677.875 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.895Z,1652991677.895 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2022-05-19T20:21:17.895Z,1652991677.895 [logger ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.896Z,1652991677.896 [logger](INFO): Join timeout helper Thread ID is 5823 2022-05-19T20:21:17.918Z,1652991677.918 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:17.919Z,1652991677.919 [logger ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.935Z,1652991677.935 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2022-05-19T20:21:17.935Z,1652991677.935 [CommandLine ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.935Z,1652991677.935 [CommandLine](INFO): Join timeout helper Thread ID is 5824 2022-05-19T20:21:17.950Z,1652991677.950 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:17.951Z,1652991677.951 [CommandLine ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.955Z,1652991677.955 [ComponentRegistry](INFO): Shutting down CommandExec ThreadHandler 2022-05-19T20:21:17.955Z,1652991677.955 [CommandExec ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.955Z,1652991677.955 [CommandExec](INFO): Join timeout helper Thread ID is 5825 2022-05-19T20:21:17.956Z,1652991677.956 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2022-05-19T20:21:17.957Z,1652991677.957 [controlThread ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:17.957Z,1652991677.957 [controlThread](INFO): Join timeout helper Thread ID is 5826 2022-05-19T20:21:18.298Z,1652991678.298 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2022-05-19T20:21:18.299Z,1652991678.299 [controlThread](DEBUG): Uninitializing ControlThread 2022-05-19T20:21:18.299Z,1652991678.299 [AHRS_M2](INFO): Powering down 2022-05-19T20:21:18.371Z,1652991678.371 [NAL9602](INFO): Powering down 2022-05-19T20:21:18.442Z,1652991678.442 [RDI_Pathfinder](INFO): Powering down 2022-05-19T20:21:18.444Z,1652991678.444 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2022-05-19T20:21:18.444Z,1652991678.444 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2022-05-19T20:21:18.445Z,1652991678.445 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2022-05-19T20:21:18.445Z,1652991678.445 [MissionManager](INFO): Uninitializing Mission Default 2022-05-19T20:21:18.445Z,1652991678.445 [Default] Stopped 2022-05-19T20:21:18.446Z,1652991678.446 [Default](DEBUG): Aggregate::uninitialize Default 2022-05-19T20:21:18.446Z,1652991678.446 [Default:B.GoToSurface] Stopped 2022-05-19T20:21:18.446Z,1652991678.446 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2022-05-19T20:21:18.446Z,1652991678.446 [Default:CheckIn] Stopped 2022-05-19T20:21:18.446Z,1652991678.446 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2022-05-19T20:21:18.446Z,1652991678.446 [Default:CheckIn:Read_Iridium] Stopped 2022-05-19T20:21:18.449Z,1652991678.449 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2022-05-19T20:21:18.449Z,1652991678.449 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2022-05-19T20:21:18.449Z,1652991678.449 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2022-05-19T20:21:18.450Z,1652991678.450 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2022-05-19T20:21:18.450Z,1652991678.450 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2022-05-19T20:21:18.450Z,1652991678.450 [BuoyancyServo](INFO): Powering down 2022-05-19T20:21:18.462Z,1652991678.462 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2022-05-19T20:21:18.462Z,1652991678.462 [ElevatorServo](INFO): Powering down 2022-05-19T20:21:18.463Z,1652991678.463 [MassServo](DEBUG): Uninitialize Mass Servo. 2022-05-19T20:21:18.463Z,1652991678.463 [MassServo](INFO): Powering down 2022-05-19T20:21:18.464Z,1652991678.464 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2022-05-19T20:21:18.464Z,1652991678.464 [RudderServo](INFO): Powering down 2022-05-19T20:21:18.465Z,1652991678.465 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2022-05-19T20:21:18.465Z,1652991678.465 [ThrusterServo](INFO): Powering down 2022-05-19T20:21:18.466Z,1652991678.466 [SBIT](DEBUG): Uninitialize SBIT Component. 2022-05-19T20:21:18.467Z,1652991678.467 [IBIT](DEBUG): Uninitialize IBIT Component. 2022-05-19T20:21:18.467Z,1652991678.467 [CBIT](DEBUG): Uninitialize CBIT Component. 2022-05-19T20:21:18.467Z,1652991678.467 [CBIT](DEBUG): Powering off loads. 2022-05-19T20:21:18.478Z,1652991678.478 [CBIT](DEBUG): Disabling WDT. 2022-05-19T20:21:18.490Z,1652991678.490 [CBIT](DEBUG): Opening all GF detection circuits. 2022-05-19T20:21:18.491Z,1652991678.491 [controlThread ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.549Z,1652991678.549 [DAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.556Z,1652991678.556 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.557Z,1652991678.557 [Onboard ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.564Z,1652991678.564 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.606Z,1652991678.606 [BackseatComponent ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.663Z,1652991678.663 [WetLabsUBAT ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.665Z,1652991678.665 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.668Z,1652991678.668 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.676Z,1652991678.676 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2022-05-19T20:21:18.773Z,1652991678.773 [logger ThreadHandler](INFO): Thread cancelled.