2019-08-09T16:30:00.922Z,1565368200.922 [CommandLine](IMPORTANT): got command restart logs 2019-08-09T16:30:18.452Z,1565368218.452 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T16:34:50.797Z,1565368490.797 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T16:34:50.797Z,1565368490.797 [Default:CheckIn:C.Wait] Stopped 2019-08-09T16:34:50.797Z,1565368490.797 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T16:34:50.797Z,1565368490.797 [Default:CheckIn:D] Running Loop=1 2019-08-09T16:34:51.196Z,1565368491.196 [Default:CheckIn:D] Stopped 2019-08-09T16:34:51.196Z,1565368491.196 [Default:CheckIn:E] Running Loop=1 2019-08-09T16:34:51.626Z,1565368491.626 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.976107 min 2019-08-09T16:34:51.626Z,1565368491.626 [Default:CheckIn:E] Stopped 2019-08-09T16:34:51.626Z,1565368491.626 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn] Stopped 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn](INFO): Running loop #9 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn] Running Loop=9 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T16:34:51.627Z,1565368491.627 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T16:34:53.198Z,1565368493.198 [NAL9602](DEBUG): Fix Requested 2019-08-09T16:34:53.593Z,1565368493.593 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163019.00,A,3647.80691,N,12150.47000,W,25.056,83.13,090819,,,D*75 2019-08-09T16:34:53.595Z,1565368493.595 [NAL9602](INFO): GPS fix at 20190809T163019: (36.796782, -121.841167) 2019-08-09T16:34:53.620Z,1565368493.620 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T16:34:53.620Z,1565368493.620 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T16:35:03.185Z,1565368503.185 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190809T141315/Courier0054.lzma 2019-08-09T16:35:03.991Z,1565368503.991 [DataOverHttps](INFO): Moved sent file to Logs/20190809T141315/Courier0054.lzma.bak 2019-08-09T16:35:03.991Z,1565368503.991 [DataOverHttps](INFO): SBD MOMSN=11546564 2019-08-09T16:35:16.125Z,1565368516.125 [DataOverHttps](INFO): Sending 214 bytes from file Logs/20190809T163000/Courier0000.lzma 2019-08-09T16:35:16.931Z,1565368516.931 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0000.lzma.bak 2019-08-09T16:35:16.931Z,1565368516.931 [DataOverHttps](INFO): SBD MOMSN=11546566 2019-08-09T16:35:17.456Z,1565368517.456 [NAL9602](INFO): SBD MO Status=2, MOMSN=16324, MT Status=2, MTMSN=0 2019-08-09T16:35:17.456Z,1565368517.456 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-09T16:35:27.869Z,1565368527.869 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190809T163000/Courier0003.lzma 2019-08-09T16:35:28.675Z,1565368528.675 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0003.lzma.bak 2019-08-09T16:35:28.675Z,1565368528.675 [DataOverHttps](INFO): SBD MOMSN=11546570 2019-08-09T16:35:40.245Z,1565368540.245 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20190809T141315/Express0055.lzma 2019-08-09T16:35:41.051Z,1565368541.051 [DataOverHttps](INFO): Moved sent file to Logs/20190809T141315/Express0055.lzma.bak 2019-08-09T16:35:41.051Z,1565368541.051 [DataOverHttps](INFO): SBD MOMSN=11546572 2019-08-09T16:35:53.158Z,1565368553.158 [DataOverHttps](INFO): Sending 350 bytes from file Logs/20190809T163000/Express0001.lzma 2019-08-09T16:35:53.963Z,1565368553.963 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0001.lzma.bak 2019-08-09T16:35:53.963Z,1565368553.963 [DataOverHttps](INFO): SBD MOMSN=11546575 2019-08-09T16:36:04.957Z,1565368564.957 [DataOverHttps](INFO): Sending 18 bytes from file Logs/20190809T163000/Express0005.lzma 2019-08-09T16:36:05.763Z,1565368565.763 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0005.lzma.bak 2019-08-09T16:36:05.763Z,1565368565.763 [DataOverHttps](INFO): SBD MOMSN=11546579 2019-08-09T16:36:06.379Z,1565368566.379 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T16:36:06.379Z,1565368566.379 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T16:36:06.379Z,1565368566.379 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T16:36:09.976Z,1565368569.976 [NAL9602](INFO): SBD MO Status=0, MOMSN=16324, MT Status=0, MTMSN=0 2019-08-09T16:36:09.976Z,1565368569.976 [NAL9602](INFO): No messages in MT queue 2019-08-09T16:36:40.679Z,1565368600.679 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T16:37:06.583Z,1565368626.583 [CBIT](IMPORTANT): Beginning ground fault scan 2019-08-09T16:37:17.498Z,1565368637.498 [CBIT](IMPORTANT): No ground fault detected mA: CHAN A0 (Batt): -0.012837 CHAN A1 (24V): 0.001129 CHAN A2 (12V): -0.002170 CHAN A3 (5V): -0.001357 CHAN B0 (3.3V): -0.000127 CHAN B1 (3.15aV): -0.000319 CHAN B2 (3.15bV): 0.000280 CHAN B3 (GND): -0.000344 OPEN: -0.000535 Full Scale Calc: 4.765 mA, -1.589 mA 2019-08-09T16:41:06.950Z,1565368866.950 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T16:41:06.950Z,1565368866.950 [Default:CheckIn:C.Wait] Stopped 2019-08-09T16:41:06.950Z,1565368866.950 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T16:41:06.951Z,1565368866.951 [Default:CheckIn:D] Running Loop=1 2019-08-09T16:41:07.348Z,1565368867.348 [Default:CheckIn:D] Stopped 2019-08-09T16:41:07.348Z,1565368867.348 [Default:CheckIn:E] Running Loop=1 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 49.245308 min 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn:E] Stopped 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn] Stopped 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn](INFO): Running loop #10 2019-08-09T16:41:07.750Z,1565368867.750 [Default:CheckIn] Running Loop=10 2019-08-09T16:41:07.751Z,1565368867.751 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T16:41:07.751Z,1565368867.751 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T16:41:09.350Z,1565368869.350 [NAL9602](DEBUG): Fix Requested 2019-08-09T16:41:09.748Z,1565368869.748 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,163634.00,A,3648.20332,N,12147.92496,W,1.886,68.74,090819,,,D*47 2019-08-09T16:41:09.751Z,1565368869.751 [NAL9602](INFO): GPS fix at 20190809T163634: (36.803389, -121.798749) 2019-08-09T16:41:09.805Z,1565368869.805 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T16:41:09.805Z,1565368869.805 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T16:41:12.848Z,1565368872.848 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190809T163000/Courier0004.lzma 2019-08-09T16:41:13.531Z,1565368873.531 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0004.lzma.bak 2019-08-09T16:41:13.531Z,1565368873.531 [DataOverHttps](INFO): SBD MOMSN=11546613 2019-08-09T16:41:19.440Z,1565368879.440 [NAL9602](INFO): SBD MO Status=0, MOMSN=16325, MT Status=0, MTMSN=0 2019-08-09T16:41:19.440Z,1565368879.440 [NAL9602](INFO): No messages in MT queue 2019-08-09T16:41:24.625Z,1565368884.625 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190809T163000/Express0006.lzma 2019-08-09T16:41:25.431Z,1565368885.431 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0006.lzma.bak 2019-08-09T16:41:25.431Z,1565368885.431 [DataOverHttps](INFO): SBD MOMSN=11546615 2019-08-09T16:41:25.949Z,1565368885.949 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T16:41:25.949Z,1565368885.949 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T16:41:25.949Z,1565368885.949 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T16:41:50.146Z,1565368910.146 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T16:46:26.546Z,1565369186.546 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T16:46:26.546Z,1565369186.546 [Default:CheckIn:C.Wait] Stopped 2019-08-09T16:46:26.546Z,1565369186.546 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T16:46:26.546Z,1565369186.546 [Default:CheckIn:D] Running Loop=1 2019-08-09T16:46:26.950Z,1565369186.950 [Default:CheckIn:D] Stopped 2019-08-09T16:46:26.950Z,1565369186.950 [Default:CheckIn:E] Running Loop=1 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 54.572017 min 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn:E] Stopped 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn] Stopped 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn](INFO): Running loop #11 2019-08-09T16:46:27.361Z,1565369187.361 [Default:CheckIn] Running Loop=11 2019-08-09T16:46:27.362Z,1565369187.362 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T16:46:27.362Z,1565369187.362 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T16:46:28.950Z,1565369188.950 [NAL9602](DEBUG): Fix Requested 2019-08-09T16:46:29.344Z,1565369189.344 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164153.00,A,3648.35956,N,12147.12207,W,1.827,198.47,090819,,,D*79 2019-08-09T16:46:29.351Z,1565369189.351 [NAL9602](INFO): GPS fix at 20190809T164153: (36.805993, -121.785368) 2019-08-09T16:46:29.447Z,1565369189.447 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T16:46:29.447Z,1565369189.447 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T16:46:33.225Z,1565369193.225 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190809T163000/Courier0009.lzma 2019-08-09T16:46:34.031Z,1565369194.031 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0009.lzma.bak 2019-08-09T16:46:34.031Z,1565369194.031 [DataOverHttps](INFO): SBD MOMSN=11546618 2019-08-09T16:46:45.053Z,1565369205.053 [DataOverHttps](INFO): Sending 133 bytes from file Logs/20190809T163000/Express0010.lzma 2019-08-09T16:46:46.670Z,1565369206.670 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0010.lzma.bak 2019-08-09T16:46:46.671Z,1565369206.671 [DataOverHttps](INFO): SBD MOMSN=11546621 2019-08-09T16:46:47.196Z,1565369207.196 [NAL9602](INFO): SBD MO Status=0, MOMSN=16326, MT Status=0, MTMSN=0 2019-08-09T16:46:47.196Z,1565369207.196 [NAL9602](INFO): No messages in MT queue 2019-08-09T16:46:47.231Z,1565369207.231 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T16:46:47.231Z,1565369207.231 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T16:46:47.231Z,1565369207.231 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T16:47:17.902Z,1565369237.902 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T16:51:47.806Z,1565369507.806 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T16:51:47.806Z,1565369507.806 [Default:CheckIn:C.Wait] Stopped 2019-08-09T16:51:47.807Z,1565369507.807 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T16:51:47.807Z,1565369507.807 [Default:CheckIn:D] Running Loop=1 2019-08-09T16:51:48.211Z,1565369508.211 [Default:CheckIn:D] Stopped 2019-08-09T16:51:48.211Z,1565369508.211 [Default:CheckIn:E] Running Loop=1 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.926367 min 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn:E] Stopped 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn] Stopped 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn](INFO): Running loop #12 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn] Running Loop=12 2019-08-09T16:51:48.626Z,1565369508.626 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T16:51:48.627Z,1565369508.627 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T16:51:50.210Z,1565369510.210 [NAL9602](DEBUG): Fix Requested 2019-08-09T16:51:50.604Z,1565369510.604 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,164714.00,A,3648.13828,N,12147.20615,W,0.136,315.00,090819,,,D*7A 2019-08-09T16:51:50.607Z,1565369510.607 [NAL9602](INFO): GPS fix at 20190809T164714: (36.802305, -121.786769) 2019-08-09T16:51:50.659Z,1565369510.659 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T16:51:50.659Z,1565369510.659 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T16:51:54.369Z,1565369514.369 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190809T163000/Courier0012.lzma 2019-08-09T16:51:55.175Z,1565369515.175 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0012.lzma.bak 2019-08-09T16:51:55.175Z,1565369515.175 [DataOverHttps](INFO): SBD MOMSN=11546667 2019-08-09T16:52:06.801Z,1565369526.801 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190809T163000/Express0013.lzma 2019-08-09T16:52:07.607Z,1565369527.607 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0013.lzma.bak 2019-08-09T16:52:07.607Z,1565369527.607 [DataOverHttps](INFO): SBD MOMSN=11546670 2019-08-09T16:52:08.237Z,1565369528.237 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T16:52:08.237Z,1565369528.237 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T16:52:08.237Z,1565369528.237 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T16:52:42.536Z,1565369562.536 [NAL9602](INFO): SBD MO Status=0, MOMSN=16327, MT Status=0, MTMSN=0 2019-08-09T16:52:42.536Z,1565369562.536 [NAL9602](INFO): No messages in MT queue 2019-08-09T16:52:44.991Z,1565369564.991 [BPC1](ERROR): BPC1B: No match for serial number 1717 in BPC1B's battery stick inventory (sticks 32-63 in onboard configuration file). 2019-08-09T16:52:44.992Z,1565369564.992 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-08-09T16:52:44.998Z,1565369564.998 [BPC1](INFO): Received data from all battery sticks. 2019-08-09T16:53:13.254Z,1565369593.254 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T16:57:08.833Z,1565369828.833 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T16:57:08.833Z,1565369828.833 [Default:CheckIn:C.Wait] Stopped 2019-08-09T16:57:08.833Z,1565369828.833 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T16:57:08.833Z,1565369828.833 [Default:CheckIn:D] Running Loop=1 2019-08-09T16:57:09.243Z,1565369829.243 [Default:CheckIn:D] Stopped 2019-08-09T16:57:09.244Z,1565369829.244 [Default:CheckIn:E] Running Loop=1 2019-08-09T16:57:09.632Z,1565369829.632 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 65.276900 min 2019-08-09T16:57:09.632Z,1565369829.632 [Default:CheckIn:E] Stopped 2019-08-09T16:57:09.632Z,1565369829.632 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn] Stopped 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn](INFO): Running loop #13 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn] Running Loop=13 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T16:57:09.633Z,1565369829.633 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T16:57:11.238Z,1565369831.238 [NAL9602](DEBUG): Fix Requested 2019-08-09T16:57:11.632Z,1565369831.632 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165235.00,A,3648.13835,N,12147.21233,W,0.136,232.09,090819,,,D*7D 2019-08-09T16:57:11.634Z,1565369831.634 [NAL9602](INFO): GPS fix at 20190809T165235: (36.802306, -121.786872) 2019-08-09T16:57:11.687Z,1565369831.687 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T16:57:11.687Z,1565369831.687 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T16:57:15.261Z,1565369835.261 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190809T163000/Courier0015.lzma 2019-08-09T16:57:16.068Z,1565369836.068 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0015.lzma.bak 2019-08-09T16:57:16.068Z,1565369836.068 [DataOverHttps](INFO): SBD MOMSN=11546674 2019-08-09T16:57:27.201Z,1565369847.201 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190809T163000/Express0016.lzma 2019-08-09T16:57:28.007Z,1565369848.007 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0016.lzma.bak 2019-08-09T16:57:28.007Z,1565369848.007 [DataOverHttps](INFO): SBD MOMSN=11546677 2019-08-09T16:57:28.280Z,1565369848.280 [NAL9602](INFO): SBD MO Status=0, MOMSN=16328, MT Status=0, MTMSN=0 2019-08-09T16:57:28.280Z,1565369848.280 [NAL9602](INFO): No messages in MT queue 2019-08-09T16:57:28.744Z,1565369848.744 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T16:57:28.744Z,1565369848.744 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T16:57:28.744Z,1565369848.744 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T16:57:58.986Z,1565369878.986 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:02:29.313Z,1565370149.313 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:02:29.314Z,1565370149.314 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:02:29.314Z,1565370149.314 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:02:29.314Z,1565370149.314 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:02:29.714Z,1565370149.714 [Default:CheckIn:D] Stopped 2019-08-09T17:02:29.714Z,1565370149.714 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:02:30.127Z,1565370150.127 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.618075 min 2019-08-09T17:02:30.127Z,1565370150.127 [Default:CheckIn:E] Stopped 2019-08-09T17:02:30.127Z,1565370150.127 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:02:30.127Z,1565370150.127 [Default:CheckIn] Stopped 2019-08-09T17:02:30.127Z,1565370150.127 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:02:30.128Z,1565370150.128 [Default:CheckIn](INFO): Running loop #14 2019-08-09T17:02:30.128Z,1565370150.128 [Default:CheckIn] Running Loop=14 2019-08-09T17:02:30.128Z,1565370150.128 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:02:30.128Z,1565370150.128 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:02:31.721Z,1565370151.721 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:02:32.117Z,1565370152.117 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,165755.00,A,3648.13959,N,12147.21128,W,0.019,232.09,090819,,,D*70 2019-08-09T17:02:32.119Z,1565370152.119 [NAL9602](INFO): GPS fix at 20190809T165755: (36.802326, -121.786855) 2019-08-09T17:02:32.157Z,1565370152.157 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:02:32.157Z,1565370152.157 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:02:35.653Z,1565370155.653 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0018.lzma 2019-08-09T17:02:36.459Z,1565370156.459 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0018.lzma.bak 2019-08-09T17:02:36.459Z,1565370156.459 [DataOverHttps](INFO): SBD MOMSN=11546719 2019-08-09T17:02:47.469Z,1565370167.469 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190809T163000/Express0019.lzma 2019-08-09T17:02:48.275Z,1565370168.275 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0019.lzma.bak 2019-08-09T17:02:48.275Z,1565370168.275 [DataOverHttps](INFO): SBD MOMSN=11546722 2019-08-09T17:02:48.803Z,1565370168.803 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:02:48.803Z,1565370168.803 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:02:48.803Z,1565370168.803 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:03:14.650Z,1565370194.650 [NAL9602](INFO): SBD MO Status=0, MOMSN=16329, MT Status=0, MTMSN=0 2019-08-09T17:03:14.650Z,1565370194.650 [NAL9602](INFO): No messages in MT queue 2019-08-09T17:03:45.355Z,1565370225.355 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:07:49.410Z,1565370469.410 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:07:49.410Z,1565370469.410 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:07:49.410Z,1565370469.410 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:07:49.410Z,1565370469.410 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:07:49.814Z,1565370469.814 [Default:CheckIn:D] Stopped 2019-08-09T17:07:49.814Z,1565370469.814 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:07:50.222Z,1565370470.222 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.953084 min 2019-08-09T17:07:50.222Z,1565370470.222 [Default:CheckIn:E] Stopped 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn] Stopped 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn](INFO): Running loop #15 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn] Running Loop=15 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:07:50.223Z,1565370470.223 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:07:51.817Z,1565370471.817 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:07:52.212Z,1565370472.212 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170314.00,A,3648.15709,N,12147.25119,W,2.546,13.83,090819,,,D*40 2019-08-09T17:07:52.219Z,1565370472.219 [NAL9602](INFO): GPS fix at 20190809T170314: (36.802618, -121.787520) 2019-08-09T17:07:52.250Z,1565370472.250 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:07:52.250Z,1565370472.250 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:07:55.666Z,1565370475.666 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0021.lzma 2019-08-09T17:07:56.403Z,1565370476.403 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0021.lzma.bak 2019-08-09T17:07:56.403Z,1565370476.403 [DataOverHttps](INFO): SBD MOMSN=11546726 2019-08-09T17:08:07.573Z,1565370487.573 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190809T163000/Express0022.lzma 2019-08-09T17:08:08.379Z,1565370488.379 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0022.lzma.bak 2019-08-09T17:08:08.380Z,1565370488.380 [DataOverHttps](INFO): SBD MOMSN=11546730 2019-08-09T17:08:09.274Z,1565370489.274 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:08:09.274Z,1565370489.274 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:08:09.274Z,1565370489.274 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:08:31.856Z,1565370511.856 [NAL9602](INFO): SBD MO Status=2, MOMSN=16330, MT Status=2, MTMSN=0 2019-08-09T17:08:31.856Z,1565370511.856 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-09T17:08:40.344Z,1565370520.344 [NAL9602](INFO): SBD MO Status=0, MOMSN=16330, MT Status=0, MTMSN=0 2019-08-09T17:08:40.344Z,1565370520.344 [NAL9602](INFO): No messages in MT queue 2019-08-09T17:09:11.043Z,1565370551.043 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:13:09.852Z,1565370789.852 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:13:09.852Z,1565370789.852 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:13:09.852Z,1565370789.852 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:13:09.853Z,1565370789.853 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:13:10.241Z,1565370790.241 [Default:CheckIn:D] Stopped 2019-08-09T17:13:10.242Z,1565370790.242 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.293530 min 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn:E] Stopped 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn] Stopped 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn](INFO): Running loop #16 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn] Running Loop=16 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:13:10.654Z,1565370790.654 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:13:12.257Z,1565370792.257 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:13:12.644Z,1565370792.644 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,170834.00,A,3648.17427,N,12147.28199,W,0.855,316.87,090819,,,D*7E 2019-08-09T17:13:12.646Z,1565370792.646 [NAL9602](INFO): GPS fix at 20190809T170834: (36.802904, -121.788033) 2019-08-09T17:13:12.690Z,1565370792.690 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:13:12.690Z,1565370792.690 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:13:18.269Z,1565370798.269 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0024.lzma 2019-08-09T17:13:19.075Z,1565370799.075 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0024.lzma.bak 2019-08-09T17:13:19.075Z,1565370799.075 [DataOverHttps](INFO): SBD MOMSN=11546856 2019-08-09T17:13:30.285Z,1565370810.285 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190809T163000/Express0025.lzma 2019-08-09T17:13:31.091Z,1565370811.091 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0025.lzma.bak 2019-08-09T17:13:31.091Z,1565370811.091 [DataOverHttps](INFO): SBD MOMSN=11546859 2019-08-09T17:13:31.654Z,1565370811.654 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:13:31.654Z,1565370811.654 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:13:31.654Z,1565370811.654 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:16:03.932Z,1565370963.932 [NAL9602](INFO): SBD MO Status=0, MOMSN=16331, MT Status=0, MTMSN=0 2019-08-09T17:16:03.932Z,1565370963.932 [NAL9602](INFO): No messages in MT queue 2019-08-09T17:16:34.635Z,1565370994.635 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:18:32.222Z,1565371112.222 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:18:32.222Z,1565371112.222 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:18:32.223Z,1565371112.223 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:18:32.223Z,1565371112.223 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:18:32.633Z,1565371112.633 [Default:CheckIn:D] Stopped 2019-08-09T17:18:32.634Z,1565371112.634 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.666732 min 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn:E] Stopped 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn] Stopped 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn](INFO): Running loop #17 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn] Running Loop=17 2019-08-09T17:18:33.031Z,1565371113.031 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:18:33.032Z,1565371113.032 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:18:34.654Z,1565371114.654 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:18:35.029Z,1565371115.029 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171356.00,A,3648.17357,N,12147.28373,W,0.330,310.73,090819,,,A*76 2019-08-09T17:18:35.031Z,1565371115.031 [NAL9602](INFO): GPS fix at 20190809T171356: (36.802893, -121.788062) 2019-08-09T17:18:35.070Z,1565371115.070 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:18:35.070Z,1565371115.070 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:18:39.045Z,1565371119.045 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190809T163000/Courier0027.lzma 2019-08-09T17:18:39.851Z,1565371119.851 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0027.lzma.bak 2019-08-09T17:18:39.851Z,1565371119.851 [DataOverHttps](INFO): SBD MOMSN=11546881 2019-08-09T17:18:49.236Z,1565371129.236 [NAL9602](INFO): SBD MO Status=0, MOMSN=16332, MT Status=0, MTMSN=0 2019-08-09T17:18:49.236Z,1565371129.236 [NAL9602](INFO): No messages in MT queue 2019-08-09T17:18:50.793Z,1565371130.793 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190809T163000/Express0028.lzma 2019-08-09T17:18:51.599Z,1565371131.599 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0028.lzma.bak 2019-08-09T17:18:51.599Z,1565371131.599 [DataOverHttps](INFO): SBD MOMSN=11546884 2019-08-09T17:18:52.542Z,1565371132.542 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:18:52.542Z,1565371132.542 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:18:52.542Z,1565371132.542 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:19:19.999Z,1565371159.999 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:23:53.171Z,1565371433.171 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:23:53.171Z,1565371433.171 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:23:53.171Z,1565371433.171 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:23:53.171Z,1565371433.171 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:23:53.576Z,1565371433.576 [Default:CheckIn:D] Stopped 2019-08-09T17:23:53.576Z,1565371433.576 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.015771 min 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn:E] Stopped 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn] Stopped 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn](INFO): Running loop #18 2019-08-09T17:23:53.986Z,1565371433.986 [Default:CheckIn] Running Loop=18 2019-08-09T17:23:53.987Z,1565371433.987 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:23:53.987Z,1565371433.987 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:23:55.585Z,1565371435.585 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:23:55.978Z,1565371435.978 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,171917.00,A,3648.16451,N,12147.28125,W,0.194,135.95,090819,,,A*79 2019-08-09T17:23:55.980Z,1565371435.980 [NAL9602](INFO): GPS fix at 20190809T171917: (36.802742, -121.788021) 2019-08-09T17:23:56.030Z,1565371436.030 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:23:56.030Z,1565371436.030 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:24:01.353Z,1565371441.353 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190809T163000/Courier0030.lzma 2019-08-09T17:24:02.159Z,1565371442.159 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0030.lzma.bak 2019-08-09T17:24:02.159Z,1565371442.159 [DataOverHttps](INFO): SBD MOMSN=11546928 2019-08-09T17:24:13.045Z,1565371453.045 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190809T163000/Express0031.lzma 2019-08-09T17:24:13.851Z,1565371453.851 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0031.lzma.bak 2019-08-09T17:24:13.851Z,1565371453.851 [DataOverHttps](INFO): SBD MOMSN=11546931 2019-08-09T17:24:14.602Z,1565371454.602 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:24:14.602Z,1565371454.602 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:24:14.602Z,1565371454.602 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:28:58.603Z,1565371738.603 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-08-09T17:29:15.198Z,1565371755.198 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:29:15.198Z,1565371755.198 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:29:15.198Z,1565371755.198 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:29:15.198Z,1565371755.198 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:29:15.589Z,1565371755.589 [Default:CheckIn:D] Stopped 2019-08-09T17:29:15.589Z,1565371755.589 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 97.382658 min 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn:E] Stopped 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn] Stopped 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn](INFO): Running loop #19 2019-08-09T17:29:16.003Z,1565371756.003 [Default:CheckIn] Running Loop=19 2019-08-09T17:29:16.004Z,1565371756.004 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:29:16.004Z,1565371756.004 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:29:17.598Z,1565371757.598 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:29:18.000Z,1565371758.000 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172438.00,A,3648.16551,N,12147.28122,W,0.214,135.95,090819,,,A*77 2019-08-09T17:29:18.002Z,1565371758.002 [NAL9602](INFO): GPS fix at 20190809T172438: (36.802759, -121.788020) 2019-08-09T17:29:18.092Z,1565371758.092 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:29:18.092Z,1565371758.092 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:29:21.465Z,1565371761.465 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0033.lzma 2019-08-09T17:29:22.271Z,1565371762.271 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0033.lzma.bak 2019-08-09T17:29:22.271Z,1565371762.271 [DataOverHttps](INFO): SBD MOMSN=11546957 2019-08-09T17:29:33.233Z,1565371773.233 [DataOverHttps](INFO): Sending 220 bytes from file Logs/20190809T163000/Express0034.lzma 2019-08-09T17:29:34.039Z,1565371774.039 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0034.lzma.bak 2019-08-09T17:29:34.039Z,1565371774.039 [DataOverHttps](INFO): SBD MOMSN=11546960 2019-08-09T17:29:34.658Z,1565371774.658 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:29:34.658Z,1565371774.658 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:29:34.658Z,1565371774.658 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:29:50.002Z,1565371790.002 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:34:35.278Z,1565372075.278 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:34:35.278Z,1565372075.278 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:34:35.278Z,1565372075.278 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:34:35.278Z,1565372075.278 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:34:35.675Z,1565372075.675 [Default:CheckIn:D] Stopped 2019-08-09T17:34:35.675Z,1565372075.675 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 102.717424 min 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn:E] Stopped 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn] Stopped 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn](INFO): Running loop #20 2019-08-09T17:34:36.087Z,1565372076.087 [Default:CheckIn] Running Loop=20 2019-08-09T17:34:36.088Z,1565372076.088 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:34:36.088Z,1565372076.088 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:34:37.686Z,1565372077.686 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:34:38.080Z,1565372078.080 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,172958.00,A,3648.16202,N,12147.28457,W,1.400,0.00,090819,,,A*73 2019-08-09T17:34:38.082Z,1565372078.082 [NAL9602](INFO): GPS fix at 20190809T172958: (36.802700, -121.788076) 2019-08-09T17:34:38.137Z,1565372078.137 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:34:38.138Z,1565372078.138 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:34:41.637Z,1565372081.637 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190809T163000/Courier0036.lzma 2019-08-09T17:34:42.443Z,1565372082.443 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0036.lzma.bak 2019-08-09T17:34:42.443Z,1565372082.443 [DataOverHttps](INFO): SBD MOMSN=11547006 2019-08-09T17:34:53.437Z,1565372093.437 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190809T163000/Express0037.lzma 2019-08-09T17:34:54.243Z,1565372094.243 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0037.lzma.bak 2019-08-09T17:34:54.243Z,1565372094.243 [DataOverHttps](INFO): SBD MOMSN=11547009 2019-08-09T17:34:55.160Z,1565372095.160 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:34:55.160Z,1565372095.160 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:34:55.160Z,1565372095.160 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:35:08.868Z,1565372108.868 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-08-09T17:35:08.950Z,1565372108.950 [NAL9602](FAULT): received: +CSQ:1 OK332, 0, 0, 0, 0 OK 2019-08-09T17:35:08.950Z,1565372108.950 [NAL9602] Data Fault, FailCount= 1 2019-08-09T17:35:08.950Z,1565372108.950 [NAL9602](ERROR): Data Fault 2019-08-09T17:35:08.987Z,1565372108.987 [CBIT](ERROR): Data Fault in component: NAL9602 2019-08-09T17:35:09.274Z,1565372109.274 [NAL9602](INFO): Powering down 2019-08-09T17:35:10.119Z,1565372110.119 [CBIT](INFO): Clearing failed state for component NAL9602 2019-08-09T17:35:10.119Z,1565372110.119 [NAL9602] No Fault, FailCount= 1 2019-08-09T17:35:39.575Z,1565372139.575 [NAL9602](INFO): Powering up NAL9602 2019-08-09T17:35:50.483Z,1565372150.483 [NAL9602](INFO): NAL9602 initialized 2019-08-09T17:36:21.588Z,1565372181.588 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:39:55.777Z,1565372395.777 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:39:55.777Z,1565372395.777 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:39:55.777Z,1565372395.777 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:39:55.778Z,1565372395.778 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:39:56.163Z,1565372396.163 [Default:CheckIn:D] Stopped 2019-08-09T17:39:56.163Z,1565372396.163 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 108.058887 min 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn:E] Stopped 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn] Stopped 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn](INFO): Running loop #21 2019-08-09T17:39:56.570Z,1565372396.570 [Default:CheckIn] Running Loop=21 2019-08-09T17:39:56.571Z,1565372396.571 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:39:56.571Z,1565372396.571 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:39:58.173Z,1565372398.173 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:00.580Z,1565372400.580 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-08-09T17:40:01.409Z,1565372401.409 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:04.230Z,1565372404.230 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:07.057Z,1565372407.057 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:10.289Z,1565372410.289 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:13.133Z,1565372413.133 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:15.949Z,1565372415.949 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:19.178Z,1565372419.178 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:22.009Z,1565372422.009 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:25.237Z,1565372425.237 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:28.069Z,1565372428.069 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:31.301Z,1565372431.301 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:34.125Z,1565372434.125 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:40:34.520Z,1565372434.520 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,173553.00,A,3648.17636,N,12147.27976,W,1.011,238.17,090819,,,A*7D 2019-08-09T17:40:34.523Z,1565372434.523 [NAL9602](INFO): GPS fix at 20190809T173553: (36.802939, -121.787996) 2019-08-09T17:40:34.579Z,1565372434.579 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:40:34.579Z,1565372434.579 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:40:38.049Z,1565372438.049 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0039.lzma 2019-08-09T17:40:38.855Z,1565372438.855 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0039.lzma.bak 2019-08-09T17:40:38.855Z,1565372438.855 [DataOverHttps](INFO): SBD MOMSN=11547041 2019-08-09T17:40:49.798Z,1565372449.798 [DataOverHttps](INFO): Sending 243 bytes from file Logs/20190809T163000/Express0040.lzma 2019-08-09T17:40:50.603Z,1565372450.603 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0040.lzma.bak 2019-08-09T17:40:50.603Z,1565372450.603 [DataOverHttps](INFO): SBD MOMSN=11547044 2019-08-09T17:40:51.163Z,1565372451.163 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:40:51.163Z,1565372451.163 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:40:51.163Z,1565372451.163 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:41:06.890Z,1565372466.890 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:45:51.730Z,1565372751.730 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:45:51.730Z,1565372751.730 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:45:51.730Z,1565372751.730 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:45:51.730Z,1565372751.730 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:45:52.137Z,1565372752.137 [Default:CheckIn:D] Stopped 2019-08-09T17:45:52.137Z,1565372752.137 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 113.991797 min 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn:E] Stopped 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn] Stopped 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn](INFO): Running loop #22 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn] Running Loop=22 2019-08-09T17:45:52.543Z,1565372752.543 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:45:52.544Z,1565372752.544 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:45:54.142Z,1565372754.142 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:45:54.536Z,1565372754.536 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174113.00,A,3648.16912,N,12147.28178,W,0.233,178.87,090819,,,A*76 2019-08-09T17:45:54.538Z,1565372754.538 [NAL9602](INFO): GPS fix at 20190809T174113: (36.802819, -121.788030) 2019-08-09T17:45:54.594Z,1565372754.594 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:45:54.594Z,1565372754.594 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:45:57.853Z,1565372757.853 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0042.lzma 2019-08-09T17:45:58.583Z,1565372758.583 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0042.lzma.bak 2019-08-09T17:45:58.583Z,1565372758.583 [DataOverHttps](INFO): SBD MOMSN=11547111 2019-08-09T17:46:09.641Z,1565372769.641 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190809T163000/Express0043.lzma 2019-08-09T17:46:10.447Z,1565372770.447 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0043.lzma.bak 2019-08-09T17:46:10.447Z,1565372770.447 [DataOverHttps](INFO): SBD MOMSN=11547114 2019-08-09T17:46:11.190Z,1565372771.190 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:46:11.190Z,1565372771.190 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:46:11.190Z,1565372771.190 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:46:31.781Z,1565372791.781 [NAL9602](INFO): SBD MO Status=0, MOMSN=16333, MT Status=0, MTMSN=0 2019-08-09T17:46:31.781Z,1565372791.781 [NAL9602](INFO): No messages in MT queue 2019-08-09T17:47:02.466Z,1565372822.466 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T17:51:11.762Z,1565373071.762 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:51:11.762Z,1565373071.762 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:51:11.762Z,1565373071.762 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:51:11.762Z,1565373071.762 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:51:12.160Z,1565373072.160 [Default:CheckIn:D] Stopped 2019-08-09T17:51:12.160Z,1565373072.160 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:51:12.582Z,1565373072.582 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 119.325505 min 2019-08-09T17:51:12.582Z,1565373072.582 [Default:CheckIn:E] Stopped 2019-08-09T17:51:12.582Z,1565373072.582 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:51:12.582Z,1565373072.582 [Default:CheckIn] Stopped 2019-08-09T17:51:12.582Z,1565373072.582 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:51:12.583Z,1565373072.583 [Default:CheckIn](INFO): Running loop #23 2019-08-09T17:51:12.583Z,1565373072.583 [Default:CheckIn] Running Loop=23 2019-08-09T17:51:12.583Z,1565373072.583 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:51:12.583Z,1565373072.583 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:51:14.170Z,1565373074.170 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:51:14.565Z,1565373074.565 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,174633.00,A,3648.16684,N,12147.28051,W,0.117,47.69,090819,,,A*41 2019-08-09T17:51:14.567Z,1565373074.567 [NAL9602](INFO): GPS fix at 20190809T174633: (36.802781, -121.788009) 2019-08-09T17:51:14.634Z,1565373074.634 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:51:14.634Z,1565373074.634 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:51:17.997Z,1565373077.997 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190809T163000/Courier0045.lzma 2019-08-09T17:51:18.803Z,1565373078.803 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0045.lzma.bak 2019-08-09T17:51:18.803Z,1565373078.803 [DataOverHttps](INFO): SBD MOMSN=11547119 2019-08-09T17:51:29.825Z,1565373089.825 [DataOverHttps](INFO): Sending 121 bytes from file Logs/20190809T163000/Express0046.lzma 2019-08-09T17:51:30.631Z,1565373090.631 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0046.lzma.bak 2019-08-09T17:51:30.631Z,1565373090.631 [DataOverHttps](INFO): SBD MOMSN=11547122 2019-08-09T17:51:31.233Z,1565373091.233 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:51:31.233Z,1565373091.233 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:51:31.234Z,1565373091.234 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:55:15.870Z,1565373315.870 [NAL9602](INFO): SBD MO Status=2, MOMSN=16334, MT Status=2, MTMSN=0 2019-08-09T17:55:15.870Z,1565373315.870 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-09T17:55:37.688Z,1565373337.688 [NAL9602](INFO): SBD MO Status=2, MOMSN=16334, MT Status=2, MTMSN=0 2019-08-09T17:55:37.688Z,1565373337.688 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-08-09T17:56:16.873Z,1565373376.873 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-08-09T17:56:31.854Z,1565373391.854 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T17:56:31.855Z,1565373391.855 [Default:CheckIn:C.Wait] Stopped 2019-08-09T17:56:31.855Z,1565373391.855 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T17:56:31.855Z,1565373391.855 [Default:CheckIn:D] Running Loop=1 2019-08-09T17:56:32.259Z,1565373392.259 [Default:CheckIn:D] Stopped 2019-08-09T17:56:32.259Z,1565373392.259 [Default:CheckIn:E] Running Loop=1 2019-08-09T17:56:32.666Z,1565373392.666 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 124.660490 min 2019-08-09T17:56:32.666Z,1565373392.666 [Default:CheckIn:E] Stopped 2019-08-09T17:56:32.666Z,1565373392.666 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T17:56:32.666Z,1565373392.666 [Default:CheckIn] Stopped 2019-08-09T17:56:32.667Z,1565373392.667 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T17:56:32.667Z,1565373392.667 [Default:CheckIn](INFO): Running loop #24 2019-08-09T17:56:32.667Z,1565373392.667 [Default:CheckIn] Running Loop=24 2019-08-09T17:56:32.667Z,1565373392.667 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T17:56:32.667Z,1565373392.667 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T17:56:34.261Z,1565373394.261 [NAL9602](DEBUG): Fix Requested 2019-08-09T17:56:34.656Z,1565373394.656 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175152.00,A,3648.16195,N,12147.28472,W,0.330,47.69,090819,,,A*45 2019-08-09T17:56:34.659Z,1565373394.659 [NAL9602](INFO): GPS fix at 20190809T175152: (36.802699, -121.788079) 2019-08-09T17:56:34.695Z,1565373394.695 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T17:56:34.695Z,1565373394.695 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T17:56:39.001Z,1565373399.001 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190809T163000/Courier0048.lzma 2019-08-09T17:56:39.807Z,1565373399.807 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0048.lzma.bak 2019-08-09T17:56:39.807Z,1565373399.807 [DataOverHttps](INFO): SBD MOMSN=11547184 2019-08-09T17:56:50.970Z,1565373410.970 [DataOverHttps](INFO): Sending 196 bytes from file Logs/20190809T163000/Express0049.lzma 2019-08-09T17:56:51.775Z,1565373411.775 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0049.lzma.bak 2019-08-09T17:56:51.775Z,1565373411.775 [DataOverHttps](INFO): SBD MOMSN=11547187 2019-08-09T17:56:52.557Z,1565373412.557 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T17:56:52.558Z,1565373412.558 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T17:56:52.558Z,1565373412.558 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T17:57:06.662Z,1565373426.662 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T18:00:11.322Z,1565373611.322 [BPC1](INFO): Calculating totals. Valid battery stick count: 56. Valid reserve battery stick count: 6. 2019-08-09T18:00:11.325Z,1565373611.325 [BPC1](INFO): Received data from all battery sticks. 2019-08-09T18:01:53.121Z,1565373713.121 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T18:01:53.122Z,1565373713.122 [Default:CheckIn:C.Wait] Stopped 2019-08-09T18:01:53.122Z,1565373713.122 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T18:01:53.122Z,1565373713.122 [Default:CheckIn:D] Running Loop=1 2019-08-09T18:01:53.526Z,1565373713.526 [Default:CheckIn:D] Stopped 2019-08-09T18:01:53.526Z,1565373713.526 [Default:CheckIn:E] Running Loop=1 2019-08-09T18:01:53.930Z,1565373713.930 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 130.014941 min 2019-08-09T18:01:53.930Z,1565373713.930 [Default:CheckIn:E] Stopped 2019-08-09T18:01:53.930Z,1565373713.930 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn] Stopped 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn](INFO): Running loop #25 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn] Running Loop=25 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T18:01:53.931Z,1565373713.931 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T18:01:55.529Z,1565373715.529 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:01:55.924Z,1565373715.924 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,175713.00,A,3648.17343,N,12147.27154,W,0.156,136.90,090819,,,A*73 2019-08-09T18:01:55.927Z,1565373715.927 [NAL9602](INFO): GPS fix at 20190809T175713: (36.802890, -121.787859) 2019-08-09T18:01:55.991Z,1565373715.991 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T18:01:55.991Z,1565373715.991 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-08-09T18:01:59.385Z,1565373719.385 [DataOverHttps](INFO): Sending 81 bytes from file Logs/20190809T163000/Courier0051.lzma 2019-08-09T18:02:00.191Z,1565373720.191 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Courier0051.lzma.bak 2019-08-09T18:02:00.191Z,1565373720.191 [DataOverHttps](INFO): SBD MOMSN=11547192 2019-08-09T18:02:11.209Z,1565373731.209 [DataOverHttps](INFO): Sending 131 bytes from file Logs/20190809T163000/Express0052.lzma 2019-08-09T18:02:12.015Z,1565373732.015 [DataOverHttps](INFO): Moved sent file to Logs/20190809T163000/Express0052.lzma.bak 2019-08-09T18:02:12.015Z,1565373732.015 [DataOverHttps](INFO): SBD MOMSN=11547195 2019-08-09T18:02:12.585Z,1565373732.585 [Default:CheckIn:Read_Iridium] Stopped 2019-08-09T18:02:12.585Z,1565373732.585 [Default:CheckIn:C.Wait] Running Loop=1 2019-08-09T18:02:12.586Z,1565373732.586 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-08-09T18:02:26.699Z,1565373746.699 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2019-08-09T18:02:26.782Z,1565373746.782 [NAL9602](FAULT): received: +CSQ:0 OK334, 2, 0, 0, 0 OK 2019-08-09T18:02:26.782Z,1565373746.782 [NAL9602] Data Fault, FailCount= 1 2019-08-09T18:02:26.782Z,1565373746.782 [NAL9602](ERROR): Data Fault 2019-08-09T18:02:26.873Z,1565373746.873 [CBIT](ERROR): Data Fault in component: NAL9602 2019-08-09T18:02:27.103Z,1565373747.103 [NAL9602](INFO): Powering down 2019-08-09T18:02:27.974Z,1565373747.974 [CBIT](INFO): Clearing failed state for component NAL9602 2019-08-09T18:02:27.975Z,1565373747.975 [NAL9602] No Fault, FailCount= 1 2019-08-09T18:02:57.403Z,1565373777.403 [NAL9602](INFO): Powering up NAL9602 2019-08-09T18:03:08.315Z,1565373788.315 [NAL9602](INFO): NAL9602 initialized 2019-08-09T18:03:39.419Z,1565373819.419 [NAL9602](INFO): Not Powering down - fast GPS 2019-08-09T18:07:13.162Z,1565374033.162 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-08-09T18:07:13.162Z,1565374033.162 [Default:CheckIn:C.Wait] Stopped 2019-08-09T18:07:13.162Z,1565374033.162 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-08-09T18:07:13.162Z,1565374033.162 [Default:CheckIn:D] Running Loop=1 2019-08-09T18:07:13.566Z,1565374033.566 [Default:CheckIn:D] Stopped 2019-08-09T18:07:13.566Z,1565374033.566 [Default:CheckIn:E] Running Loop=1 2019-08-09T18:07:13.970Z,1565374033.970 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 135.348942 min 2019-08-09T18:07:13.970Z,1565374033.970 [Default:CheckIn:E] Stopped 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn] Stopped 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn](INFO): Running loop #26 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn] Running Loop=26 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-08-09T18:07:13.971Z,1565374033.971 [Default:CheckIn:Read_GPS] Running Loop=1 2019-08-09T18:07:15.570Z,1565374035.570 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:17.999Z,1565374037.999 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-08-09T18:07:18.805Z,1565374038.805 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:21.225Z,1565374041.225 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:24.465Z,1565374044.465 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:27.285Z,1565374047.285 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:30.517Z,1565374050.517 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:33.349Z,1565374053.349 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:36.173Z,1565374056.173 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:38.193Z,1565374058.193 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:41.425Z,1565374061.425 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:44.262Z,1565374064.262 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:47.486Z,1565374067.486 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:50.314Z,1565374070.314 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:53.558Z,1565374073.558 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:56.377Z,1565374076.377 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:07:59.201Z,1565374079.201 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:01.225Z,1565374081.225 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:03.249Z,1565374083.249 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:06.481Z,1565374086.481 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:09.301Z,1565374089.301 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:12.533Z,1565374092.533 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:15.361Z,1565374095.361 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:18.594Z,1565374098.594 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:21.421Z,1565374101.421 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:24.249Z,1565374104.249 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:26.279Z,1565374106.279 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:29.509Z,1565374109.509 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:32.338Z,1565374112.338 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:35.569Z,1565374115.569 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:38.235Z,1565374118.235 [CommandLine](IMPORTANT): got command quit 2019-08-09T18:08:38.397Z,1565374118.397 [NAL9602](DEBUG): Fix Requested 2019-08-09T18:08:39.241Z,1565374119.241 [Supervisor](INFO): Stop Mission called by Supervisor::terminate 2019-08-09T18:08:39.242Z,1565374119.242 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:39.242Z,1565374119.242 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.317Z,1565374119.317 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-08-09T18:08:39.318Z,1565374119.318 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.318Z,1565374119.318 [CommandLine](INFO): Join timeout helper Thread ID is 5116 2019-08-09T18:08:39.322Z,1565374119.322 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-08-09T18:08:39.322Z,1565374119.322 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.322Z,1565374119.322 [NavChartDb](INFO): Join timeout helper Thread ID is 5117 2019-08-09T18:08:39.398Z,1565374119.398 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:39.398Z,1565374119.398 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.405Z,1565374119.405 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-08-09T18:08:39.406Z,1565374119.406 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.406Z,1565374119.406 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 5118 2019-08-09T18:08:39.586Z,1565374119.586 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:39.586Z,1565374119.586 [WetLabsBB2FL](INFO): Powering down 2019-08-09T18:08:39.587Z,1565374119.587 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.594Z,1565374119.594 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-08-09T18:08:39.594Z,1565374119.594 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.594Z,1565374119.594 [CTD_Seabird](INFO): Join timeout helper Thread ID is 5119 2019-08-09T18:08:39.650Z,1565374119.650 [CTD_Seabird](INFO): Powering down 2019-08-09T18:08:39.662Z,1565374119.662 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:39.662Z,1565374119.662 [CTD_Seabird](INFO): Powering down 2019-08-09T18:08:39.674Z,1565374119.674 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.693Z,1565374119.693 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-08-09T18:08:39.694Z,1565374119.694 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.694Z,1565374119.694 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5120 2019-08-09T18:08:39.762Z,1565374119.762 [CTD_NeilBrown](INFO): Powering down 2019-08-09T18:08:39.774Z,1565374119.774 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:39.774Z,1565374119.774 [CTD_NeilBrown](INFO): Powering down 2019-08-09T18:08:39.785Z,1565374119.785 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.794Z,1565374119.794 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-08-09T18:08:39.794Z,1565374119.794 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:39.795Z,1565374119.795 [Radio_Surface](INFO): Join timeout helper Thread ID is 5121 2019-08-09T18:08:40.150Z,1565374120.150 [Radio_Surface](INFO): Powering down 2019-08-09T18:08:40.150Z,1565374120.150 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:40.151Z,1565374120.151 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.158Z,1565374120.158 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-08-09T18:08:40.158Z,1565374120.158 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.159Z,1565374120.159 [DataOverHttps](INFO): Join timeout helper Thread ID is 5122 2019-08-09T18:08:40.282Z,1565374120.282 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:40.282Z,1565374120.282 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.298Z,1565374120.298 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-08-09T18:08:40.298Z,1565374120.298 [logger ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.299Z,1565374120.299 [logger](INFO): Join timeout helper Thread ID is 5123 2019-08-09T18:08:40.350Z,1565374120.350 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:40.350Z,1565374120.350 [logger ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.358Z,1565374120.358 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-08-09T18:08:40.358Z,1565374120.358 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.358Z,1565374120.358 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-08-09T18:08:40.359Z,1565374120.359 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.359Z,1565374120.359 [controlThread](INFO): Join timeout helper Thread ID is 5124 2019-08-09T18:08:40.382Z,1565374120.382 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-08-09T18:08:40.382Z,1565374120.382 [controlThread](DEBUG): Uninitializing ControlThread 2019-08-09T18:08:40.382Z,1565374120.382 [AHRS_M2](INFO): Powering down 2019-08-09T18:08:40.454Z,1565374120.454 [NAL9602](INFO): Powering down 2019-08-09T18:08:40.456Z,1565374120.456 [Aanderaa_O2](INFO): Powering down 2019-08-09T18:08:40.458Z,1565374120.458 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-08-09T18:08:40.459Z,1565374120.459 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-08-09T18:08:40.459Z,1565374120.459 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-08-09T18:08:40.460Z,1565374120.460 [MissionManager](INFO): Uninitializing Mission Default 2019-08-09T18:08:40.460Z,1565374120.460 [Default] Stopped 2019-08-09T18:08:40.460Z,1565374120.460 [Default](DEBUG): Aggregate::uninitialize Default 2019-08-09T18:08:40.460Z,1565374120.460 [Default:B.GoToSurface] Stopped 2019-08-09T18:08:40.460Z,1565374120.460 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-08-09T18:08:40.460Z,1565374120.460 [Default:CheckIn] Stopped 2019-08-09T18:08:40.460Z,1565374120.460 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-08-09T18:08:40.460Z,1565374120.460 [Default:CheckIn:Read_GPS] Stopped 2019-08-09T18:08:40.463Z,1565374120.463 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-08-09T18:08:40.463Z,1565374120.463 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-08-09T18:08:40.463Z,1565374120.463 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-08-09T18:08:40.464Z,1565374120.464 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-08-09T18:08:40.464Z,1565374120.464 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-08-09T18:08:40.464Z,1565374120.464 [BuoyancyServo](INFO): Powering down 2019-08-09T18:08:40.478Z,1565374120.478 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-08-09T18:08:40.478Z,1565374120.478 [ElevatorServo](INFO): Powering down 2019-08-09T18:08:40.479Z,1565374120.479 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-08-09T18:08:40.479Z,1565374120.479 [MassServo](INFO): Powering down 2019-08-09T18:08:40.479Z,1565374120.479 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-08-09T18:08:40.480Z,1565374120.480 [RudderServo](INFO): Powering down 2019-08-09T18:08:40.480Z,1565374120.480 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-08-09T18:08:40.480Z,1565374120.480 [ThrusterServo](INFO): Powering down 2019-08-09T18:08:40.481Z,1565374120.481 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-08-09T18:08:40.482Z,1565374120.482 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-08-09T18:08:40.482Z,1565374120.482 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-08-09T18:08:40.482Z,1565374120.482 [CBIT](DEBUG): Powering off loads. 2019-08-09T18:08:40.493Z,1565374120.493 [CBIT](DEBUG): Disabling WDT. 2019-08-09T18:08:40.505Z,1565374120.505 [CBIT](DEBUG): Opening all GF detection circuits. 2019-08-09T18:08:40.506Z,1565374120.506 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.594Z,1565374120.594 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.600Z,1565374120.600 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.631Z,1565374120.631 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.633Z,1565374120.633 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.640Z,1565374120.640 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.678Z,1565374120.678 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-08-09T18:08:40.776Z,1565374120.776 [logger ThreadHandler](INFO): Thread cancelled.