2019-09-12T20:14:20.998Z,1568319260.998 [CommandLine](IMPORTANT): got command restart logs 2019-09-12T20:14:29.163Z,1568319269.163 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:14:29.163Z,1568319269.163 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:14:29.163Z,1568319269.163 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:14:29.164Z,1568319269.164 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:14:29.558Z,1568319269.558 [Default:CheckIn:D] Stopped 2019-09-12T20:14:29.558Z,1568319269.558 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 30.046651 min 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn:E] Stopped 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn] Stopped 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:14:29.944Z,1568319269.944 [Default:CheckIn](INFO): Running loop #6 2019-09-12T20:14:29.949Z,1568319269.949 [Default:CheckIn] Running Loop=6 2019-09-12T20:14:29.949Z,1568319269.949 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:14:29.949Z,1568319269.949 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:14:31.549Z,1568319271.549 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:14:31.926Z,1568319271.926 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,200935.00,A,3648.00536,N,12149.53523,W,7.387,256.80,120919,,,A*75 2019-09-12T20:14:31.928Z,1568319271.928 [NAL9602](INFO): GPS fix at 20190912T200935: (36.800089, -121.825587) 2019-09-12T20:14:31.992Z,1568319271.992 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:14:31.992Z,1568319271.992 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:14:39.197Z,1568319279.197 [NAL9602](INFO): SBD MO Status=0, MOMSN=16868, MT Status=0, MTMSN=0 2019-09-12T20:14:39.197Z,1568319279.197 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:14:39.656Z,1568319279.656 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T171221/Courier0072.lzma 2019-09-12T20:14:41.662Z,1568319281.662 [DataOverHttps](INFO): Moved sent file to Logs/20190912T171221/Courier0072.lzma.bak 2019-09-12T20:14:41.663Z,1568319281.663 [DataOverHttps](INFO): SBD MOMSN=11777027 2019-09-12T20:14:58.649Z,1568319298.649 [DataOverHttps](INFO): Sending 215 bytes from file Logs/20190912T201420/Courier0000.lzma 2019-09-12T20:15:00.682Z,1568319300.682 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0000.lzma.bak 2019-09-12T20:15:00.682Z,1568319300.682 [DataOverHttps](INFO): SBD MOMSN=11777032 2019-09-12T20:15:09.906Z,1568319309.906 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:15:17.704Z,1568319317.704 [DataOverHttps](INFO): Sending 25 bytes from file Logs/20190912T201420/Courier0003.lzma 2019-09-12T20:15:19.710Z,1568319319.710 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0003.lzma.bak 2019-09-12T20:15:19.710Z,1568319319.710 [DataOverHttps](INFO): SBD MOMSN=11777037 2019-09-12T20:15:36.644Z,1568319336.644 [DataOverHttps](INFO): Sending 95 bytes from file Logs/20190912T171221/Express0073.lzma 2019-09-12T20:15:38.650Z,1568319338.650 [DataOverHttps](INFO): Moved sent file to Logs/20190912T171221/Express0073.lzma.bak 2019-09-12T20:15:38.651Z,1568319338.651 [DataOverHttps](INFO): SBD MOMSN=11777039 2019-09-12T20:15:55.633Z,1568319355.633 [DataOverHttps](INFO): Sending 341 bytes from file Logs/20190912T201420/Express0001.lzma 2019-09-12T20:15:57.638Z,1568319357.638 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0001.lzma.bak 2019-09-12T20:15:57.638Z,1568319357.638 [DataOverHttps](INFO): SBD MOMSN=11777042 2019-09-12T20:16:14.880Z,1568319374.880 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20190912T201420/Express0004.lzma 2019-09-12T20:16:16.886Z,1568319376.886 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0004.lzma.bak 2019-09-12T20:16:16.886Z,1568319376.886 [DataOverHttps](INFO): SBD MOMSN=11777046 2019-09-12T20:16:18.231Z,1568319378.231 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:16:18.231Z,1568319378.231 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:16:18.231Z,1568319378.231 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:21:18.818Z,1568319678.818 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:21:18.818Z,1568319678.818 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:21:18.818Z,1568319678.818 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:21:18.819Z,1568319678.819 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:21:19.197Z,1568319679.197 [Default:CheckIn:D] Stopped 2019-09-12T20:21:19.197Z,1568319679.197 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 36.873979 min 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn:E] Stopped 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn] Stopped 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn](INFO): Running loop #7 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn] Running Loop=7 2019-09-12T20:21:19.658Z,1568319679.658 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:21:19.659Z,1568319679.659 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:21:21.189Z,1568319681.189 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:21:21.584Z,1568319681.584 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,201624.00,A,3648.22237,N,12148.46287,W,26.728,70.51,120919,,,A*79 2019-09-12T20:21:21.588Z,1568319681.588 [NAL9602](INFO): GPS fix at 20190912T201624: (36.803706, -121.807715) 2019-09-12T20:21:21.651Z,1568319681.651 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:21:21.651Z,1568319681.651 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:21:22.801Z,1568319682.801 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:21:29.432Z,1568319689.432 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T201420/Courier0006.lzma 2019-09-12T20:21:31.438Z,1568319691.438 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0006.lzma.bak 2019-09-12T20:21:31.438Z,1568319691.438 [DataOverHttps](INFO): SBD MOMSN=11777102 2019-09-12T20:21:41.377Z,1568319701.377 [NAL9602](INFO): SBD MO Status=2, MOMSN=16869, MT Status=2, MTMSN=0 2019-09-12T20:21:41.377Z,1568319701.377 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T20:21:48.412Z,1568319708.412 [DataOverHttps](INFO): Sending 136 bytes from file Logs/20190912T201420/Express0007.lzma 2019-09-12T20:21:50.420Z,1568319710.420 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0007.lzma.bak 2019-09-12T20:21:50.420Z,1568319710.420 [DataOverHttps](INFO): SBD MOMSN=11777106 2019-09-12T20:21:51.913Z,1568319711.913 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:21:51.913Z,1568319711.913 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:21:51.913Z,1568319711.913 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:21:59.563Z,1568319719.563 [NAL9602](INFO): SBD MO Status=2, MOMSN=16869, MT Status=2, MTMSN=0 2019-09-12T20:21:59.563Z,1568319719.563 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T20:22:36.727Z,1568319756.727 [NAL9602](INFO): SBD MO Status=0, MOMSN=16869, MT Status=0, MTMSN=0 2019-09-12T20:22:36.727Z,1568319756.727 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:23:07.427Z,1568319787.427 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:26:52.529Z,1568320012.529 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:26:52.529Z,1568320012.529 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:26:52.529Z,1568320012.529 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:26:52.529Z,1568320012.529 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:26:52.914Z,1568320012.914 [Default:CheckIn:D] Stopped 2019-09-12T20:26:52.914Z,1568320012.914 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 42.435921 min 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn:E] Stopped 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn] Stopped 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn](INFO): Running loop #8 2019-09-12T20:26:53.323Z,1568320013.323 [Default:CheckIn] Running Loop=8 2019-09-12T20:26:53.324Z,1568320013.324 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:26:53.324Z,1568320013.324 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:26:54.925Z,1568320014.925 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:26:55.320Z,1568320015.320 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202157.00,A,3648.35336,N,12147.12579,W,5.365,180.85,120919,,,A*7C 2019-09-12T20:26:55.332Z,1568320015.332 [NAL9602](INFO): GPS fix at 20190912T202157: (36.805889, -121.785430) 2019-09-12T20:26:55.356Z,1568320015.356 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:26:55.357Z,1568320015.357 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:26:57.345Z,1568320017.345 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:27:02.680Z,1568320022.680 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190912T201420/Courier0009.lzma 2019-09-12T20:27:04.686Z,1568320024.686 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0009.lzma.bak 2019-09-12T20:27:04.686Z,1568320024.686 [DataOverHttps](INFO): SBD MOMSN=11777128 2019-09-12T20:27:13.091Z,1568320033.091 [NAL9602](INFO): SBD MO Status=0, MOMSN=16870, MT Status=0, MTMSN=0 2019-09-12T20:27:13.091Z,1568320033.091 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:27:24.804Z,1568320044.804 [DataOverHttps](INFO): Sending 134 bytes from file Logs/20190912T201420/Express0010.lzma 2019-09-12T20:27:26.810Z,1568320046.810 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0010.lzma.bak 2019-09-12T20:27:26.810Z,1568320046.810 [DataOverHttps](INFO): SBD MOMSN=11777132 2019-09-12T20:27:28.107Z,1568320048.107 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:27:28.107Z,1568320048.107 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:27:28.107Z,1568320048.107 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:27:43.822Z,1568320063.822 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:32:28.737Z,1568320348.737 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:32:28.737Z,1568320348.737 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:32:28.737Z,1568320348.737 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:32:28.737Z,1568320348.737 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:32:29.143Z,1568320349.143 [Default:CheckIn:D] Stopped 2019-09-12T20:32:29.143Z,1568320349.143 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:32:29.519Z,1568320349.519 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 48.039734 min 2019-09-12T20:32:29.519Z,1568320349.519 [Default:CheckIn:E] Stopped 2019-09-12T20:32:29.519Z,1568320349.519 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:32:29.519Z,1568320349.519 [Default:CheckIn] Stopped 2019-09-12T20:32:29.519Z,1568320349.519 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:32:29.520Z,1568320349.520 [Default:CheckIn](INFO): Running loop #9 2019-09-12T20:32:29.520Z,1568320349.520 [Default:CheckIn] Running Loop=9 2019-09-12T20:32:29.520Z,1568320349.520 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:32:29.520Z,1568320349.520 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:32:31.077Z,1568320351.077 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:32:31.467Z,1568320351.467 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,202733.00,A,3648.15078,N,12147.22474,W,0.136,224.40,120919,,,D*7C 2019-09-12T20:32:31.469Z,1568320351.469 [NAL9602](INFO): GPS fix at 20190912T202733: (36.802513, -121.787079) 2019-09-12T20:32:31.498Z,1568320351.498 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:32:31.498Z,1568320351.498 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:32:33.106Z,1568320353.106 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:32:38.632Z,1568320358.632 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190912T201420/Courier0012.lzma 2019-09-12T20:32:40.638Z,1568320360.638 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0012.lzma.bak 2019-09-12T20:32:40.638Z,1568320360.638 [DataOverHttps](INFO): SBD MOMSN=11777149 2019-09-12T20:32:49.243Z,1568320369.243 [NAL9602](INFO): SBD MO Status=0, MOMSN=16871, MT Status=0, MTMSN=0 2019-09-12T20:32:49.243Z,1568320369.243 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:32:57.756Z,1568320377.756 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190912T201420/Express0013.lzma 2019-09-12T20:32:59.763Z,1568320379.763 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0013.lzma.bak 2019-09-12T20:32:59.763Z,1568320379.763 [DataOverHttps](INFO): SBD MOMSN=11777152 2019-09-12T20:33:00.990Z,1568320380.990 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:33:00.990Z,1568320380.990 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:33:00.990Z,1568320380.990 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:33:19.944Z,1568320399.944 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:37:04.588Z,1568320624.588 [BPC1](ERROR): Battery stick #36 (s/n: 0276) reported OVER_TEMP_ALARM. Status code: 0x1717. 2019-09-12T20:37:04.589Z,1568320624.589 [BPC1](INFO): Calculating totals. Valid battery stick count: 55. Valid reserve battery stick count: 6. 2019-09-12T20:37:04.591Z,1568320624.591 [BPC1](INFO): Received data from all battery sticks. 2019-09-12T20:38:01.554Z,1568320681.554 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:38:01.554Z,1568320681.554 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:38:01.554Z,1568320681.554 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:38:01.554Z,1568320681.554 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:38:01.977Z,1568320681.977 [Default:CheckIn:D] Stopped 2019-09-12T20:38:01.977Z,1568320681.977 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:38:02.377Z,1568320682.377 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 53.586975 min 2019-09-12T20:38:02.377Z,1568320682.377 [Default:CheckIn:E] Stopped 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn] Stopped 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn](INFO): Running loop #10 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn] Running Loop=10 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:38:02.378Z,1568320682.378 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:38:03.973Z,1568320683.973 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:38:04.368Z,1568320684.368 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203305.00,A,3648.18241,N,12147.27925,W,0.097,358.71,120919,,,D*77 2019-09-12T20:38:04.370Z,1568320684.370 [NAL9602](INFO): GPS fix at 20190912T203305: (36.803040, -121.787987) 2019-09-12T20:38:04.414Z,1568320684.414 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:38:04.415Z,1568320684.415 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:38:12.180Z,1568320692.180 [DataOverHttps](INFO): Sending 222 bytes from file Logs/20190912T201420/Courier0015.lzma 2019-09-12T20:38:14.186Z,1568320694.186 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0015.lzma.bak 2019-09-12T20:38:14.186Z,1568320694.186 [DataOverHttps](INFO): SBD MOMSN=11777201 2019-09-12T20:38:24.159Z,1568320704.159 [NAL9602](INFO): SBD MO Status=0, MOMSN=16872, MT Status=0, MTMSN=0 2019-09-12T20:38:24.159Z,1568320704.159 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:38:31.196Z,1568320711.196 [DataOverHttps](INFO): Sending 135 bytes from file Logs/20190912T201420/Express0016.lzma 2019-09-12T20:38:33.202Z,1568320713.202 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0016.lzma.bak 2019-09-12T20:38:33.202Z,1568320713.202 [DataOverHttps](INFO): SBD MOMSN=11777205 2019-09-12T20:38:34.685Z,1568320714.685 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:38:34.685Z,1568320714.685 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:38:34.685Z,1568320714.685 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:38:54.886Z,1568320734.886 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:43:35.272Z,1568321015.272 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:43:35.272Z,1568321015.272 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:43:35.272Z,1568321015.272 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:43:35.273Z,1568321015.273 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:43:35.678Z,1568321015.678 [Default:CheckIn:D] Stopped 2019-09-12T20:43:35.678Z,1568321015.678 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:43:36.072Z,1568321016.072 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 59.148657 min 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn:E] Stopped 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn] Stopped 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn](INFO): Running loop #11 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn] Running Loop=11 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:43:36.073Z,1568321016.073 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:43:37.677Z,1568321017.677 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:43:38.071Z,1568321018.071 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,203839.00,A,3648.17786,N,12147.27804,W,0.156,347.58,120919,,,A*7C 2019-09-12T20:43:38.074Z,1568321018.074 [NAL9602](INFO): GPS fix at 20190912T203839: (36.802964, -121.787967) 2019-09-12T20:43:38.097Z,1568321018.097 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:43:38.097Z,1568321018.097 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:43:40.104Z,1568321020.104 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:43:45.332Z,1568321025.332 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190912T201420/Courier0018.lzma 2019-09-12T20:43:47.338Z,1568321027.338 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0018.lzma.bak 2019-09-12T20:43:47.338Z,1568321027.338 [DataOverHttps](INFO): SBD MOMSN=11777228 2019-09-12T20:43:54.225Z,1568321034.225 [NAL9602](INFO): SBD MO Status=2, MOMSN=16873, MT Status=2, MTMSN=0 2019-09-12T20:43:54.225Z,1568321034.225 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T20:44:04.320Z,1568321044.320 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T201420/Express0019.lzma 2019-09-12T20:44:06.326Z,1568321046.326 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0019.lzma.bak 2019-09-12T20:44:06.327Z,1568321046.327 [DataOverHttps](INFO): SBD MOMSN=11777231 2019-09-12T20:44:07.590Z,1568321047.590 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:44:07.591Z,1568321047.591 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:44:07.591Z,1568321047.591 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:47:31.581Z,1568321251.581 [NAL9602](INFO): SBD MO Status=0, MOMSN=16873, MT Status=0, MTMSN=0 2019-09-12T20:47:31.581Z,1568321251.581 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:48:02.285Z,1568321282.285 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:49:08.168Z,1568321348.168 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:49:08.168Z,1568321348.168 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:49:08.168Z,1568321348.168 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:49:08.169Z,1568321348.169 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:49:08.581Z,1568321348.581 [Default:CheckIn:D] Stopped 2019-09-12T20:49:08.581Z,1568321348.581 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:49:08.973Z,1568321348.973 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 64.697042 min 2019-09-12T20:49:08.973Z,1568321348.973 [Default:CheckIn:E] Stopped 2019-09-12T20:49:08.973Z,1568321348.973 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn] Stopped 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn](INFO): Running loop #12 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn] Running Loop=12 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:49:08.974Z,1568321348.974 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:49:10.577Z,1568321350.577 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:49:10.982Z,1568321350.982 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204411.00,A,3648.17690,N,12147.27900,W,0.233,347.58,120919,,,A*7E 2019-09-12T20:49:10.984Z,1568321350.984 [NAL9602](INFO): GPS fix at 20190912T204411: (36.802948, -121.787983) 2019-09-12T20:49:11.048Z,1568321351.048 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:49:11.048Z,1568321351.048 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:49:12.657Z,1568321352.657 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:49:18.344Z,1568321358.344 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T201420/Courier0021.lzma 2019-09-12T20:49:20.350Z,1568321360.350 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0021.lzma.bak 2019-09-12T20:49:20.350Z,1568321360.350 [DataOverHttps](INFO): SBD MOMSN=11777265 2019-09-12T20:49:24.711Z,1568321364.711 [NAL9602](INFO): SBD MO Status=0, MOMSN=16874, MT Status=0, MTMSN=0 2019-09-12T20:49:24.711Z,1568321364.711 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:49:37.716Z,1568321377.716 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T201420/Express0022.lzma 2019-09-12T20:49:39.722Z,1568321379.722 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0022.lzma.bak 2019-09-12T20:49:39.722Z,1568321379.722 [DataOverHttps](INFO): SBD MOMSN=11777269 2019-09-12T20:49:40.925Z,1568321380.925 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:49:40.925Z,1568321380.925 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:49:40.925Z,1568321380.925 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:49:55.412Z,1568321395.412 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T20:54:41.467Z,1568321681.467 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T20:54:41.467Z,1568321681.467 [Default:CheckIn:C.Wait] Stopped 2019-09-12T20:54:41.467Z,1568321681.467 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T20:54:41.467Z,1568321681.467 [Default:CheckIn:D] Running Loop=1 2019-09-12T20:54:41.878Z,1568321681.878 [Default:CheckIn:D] Stopped 2019-09-12T20:54:41.878Z,1568321681.878 [Default:CheckIn:E] Running Loop=1 2019-09-12T20:54:42.287Z,1568321682.287 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 70.251986 min 2019-09-12T20:54:42.287Z,1568321682.287 [Default:CheckIn:E] Stopped 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn] Stopped 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn](INFO): Running loop #13 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn] Running Loop=13 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T20:54:42.288Z,1568321682.288 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T20:54:43.881Z,1568321683.881 [NAL9602](DEBUG): Fix Requested 2019-09-12T20:54:44.274Z,1568321684.274 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,204944.00,A,3648.17559,N,12147.27747,W,0.233,131.82,120919,,,A*7C 2019-09-12T20:54:44.276Z,1568321684.276 [NAL9602](INFO): GPS fix at 20190912T204944: (36.802926, -121.787958) 2019-09-12T20:54:44.323Z,1568321684.323 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T20:54:44.323Z,1568321684.323 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T20:54:46.306Z,1568321686.306 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T20:54:52.104Z,1568321692.104 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T201420/Courier0024.lzma 2019-09-12T20:54:54.110Z,1568321694.110 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0024.lzma.bak 2019-09-12T20:54:54.110Z,1568321694.110 [DataOverHttps](INFO): SBD MOMSN=11777304 2019-09-12T20:55:11.100Z,1568321711.100 [DataOverHttps](INFO): Sending 119 bytes from file Logs/20190912T201420/Express0025.lzma 2019-09-12T20:55:13.106Z,1568321713.106 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0025.lzma.bak 2019-09-12T20:55:13.106Z,1568321713.106 [DataOverHttps](INFO): SBD MOMSN=11777307 2019-09-12T20:55:14.239Z,1568321714.239 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T20:55:14.239Z,1568321714.239 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T20:55:14.239Z,1568321714.239 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T20:56:36.599Z,1568321796.599 [NAL9602](INFO): SBD MO Status=0, MOMSN=16875, MT Status=0, MTMSN=0 2019-09-12T20:56:36.599Z,1568321796.599 [NAL9602](INFO): No messages in MT queue 2019-09-12T20:57:07.291Z,1568321827.291 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:00:14.810Z,1568322014.810 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:00:14.810Z,1568322014.810 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:00:14.810Z,1568322014.810 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:00:14.810Z,1568322014.810 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:00:15.226Z,1568322015.226 [Default:CheckIn:D] Stopped 2019-09-12T21:00:15.226Z,1568322015.226 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 75.807788 min 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn:E] Stopped 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn] Stopped 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn](INFO): Running loop #14 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn] Running Loop=14 2019-09-12T21:00:15.613Z,1568322015.613 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:00:15.614Z,1568322015.614 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:00:17.221Z,1568322017.221 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:00:17.614Z,1568322017.614 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,205517.00,A,3648.17506,N,12147.27884,W,0.136,131.82,120919,,,A*7B 2019-09-12T21:00:17.616Z,1568322017.616 [NAL9602](INFO): GPS fix at 20190912T205517: (36.802918, -121.787981) 2019-09-12T21:00:17.640Z,1568322017.640 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:00:17.640Z,1568322017.640 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:00:19.631Z,1568322019.631 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:00:24.805Z,1568322024.805 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T201420/Courier0027.lzma 2019-09-12T21:00:26.810Z,1568322026.810 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0027.lzma.bak 2019-09-12T21:00:26.810Z,1568322026.810 [DataOverHttps](INFO): SBD MOMSN=11777347 2019-09-12T21:00:43.992Z,1568322043.992 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T201420/Express0028.lzma 2019-09-12T21:00:45.998Z,1568322045.998 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0028.lzma.bak 2019-09-12T21:00:45.998Z,1568322045.998 [DataOverHttps](INFO): SBD MOMSN=11777350 2019-09-12T21:00:47.122Z,1568322047.122 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:00:47.122Z,1568322047.122 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:00:47.122Z,1568322047.122 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:00:47.911Z,1568322047.911 [NAL9602](INFO): SBD MO Status=0, MOMSN=16876, MT Status=0, MTMSN=0 2019-09-12T21:00:47.911Z,1568322047.911 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:01:18.610Z,1568322078.610 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:05:47.775Z,1568322347.775 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:05:47.775Z,1568322347.775 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:05:47.775Z,1568322347.775 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:05:47.775Z,1568322347.775 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:05:48.159Z,1568322348.159 [Default:CheckIn:D] Stopped 2019-09-12T21:05:48.159Z,1568322348.159 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 81.356673 min 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn:E] Stopped 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn] Stopped 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:05:48.573Z,1568322348.573 [Default:CheckIn](INFO): Running loop #15 2019-09-12T21:05:48.574Z,1568322348.574 [Default:CheckIn] Running Loop=15 2019-09-12T21:05:48.574Z,1568322348.574 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:05:48.574Z,1568322348.574 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:05:50.189Z,1568322350.189 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:05:50.567Z,1568322350.567 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210049.00,A,3648.17304,N,12147.27875,W,0.078,131.82,120919,,,A*70 2019-09-12T21:05:50.570Z,1568322350.570 [NAL9602](INFO): GPS fix at 20190912T210049: (36.802884, -121.787979) 2019-09-12T21:05:50.612Z,1568322350.612 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:05:50.612Z,1568322350.612 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:05:52.186Z,1568322352.186 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:05:57.992Z,1568322357.992 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T201420/Courier0030.lzma 2019-09-12T21:05:59.998Z,1568322359.998 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0030.lzma.bak 2019-09-12T21:05:59.999Z,1568322359.999 [DataOverHttps](INFO): SBD MOMSN=11777375 2019-09-12T21:06:16.976Z,1568322376.976 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T201420/Express0031.lzma 2019-09-12T21:06:18.984Z,1568322378.984 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0031.lzma.bak 2019-09-12T21:06:18.984Z,1568322378.984 [DataOverHttps](INFO): SBD MOMSN=11777379 2019-09-12T21:06:20.494Z,1568322380.494 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:06:20.494Z,1568322380.494 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:06:20.494Z,1568322380.494 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:06:49.951Z,1568322409.951 [NAL9602](INFO): SBD MO Status=2, MOMSN=16877, MT Status=2, MTMSN=0 2019-09-12T21:06:49.952Z,1568322409.952 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:07:15.815Z,1568322435.815 [NAL9602](INFO): SBD MO Status=2, MOMSN=16877, MT Status=2, MTMSN=0 2019-09-12T21:07:15.815Z,1568322435.815 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:08:18.059Z,1568322498.059 [NAL9602](INFO): SBD MO Status=0, MOMSN=16877, MT Status=0, MTMSN=0 2019-09-12T21:08:18.059Z,1568322498.059 [NAL9602](INFO): No messages in MT queue 2019-09-12T21:08:48.762Z,1568322528.762 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:11:21.089Z,1568322681.089 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:11:21.089Z,1568322681.089 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:11:21.089Z,1568322681.089 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:11:21.089Z,1568322681.089 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:11:21.499Z,1568322681.499 [Default:CheckIn:D] Stopped 2019-09-12T21:11:21.499Z,1568322681.499 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:11:21.908Z,1568322681.908 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 86.912345 min 2019-09-12T21:11:21.908Z,1568322681.908 [Default:CheckIn:E] Stopped 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn] Stopped 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn](INFO): Running loop #16 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn] Running Loop=16 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:11:21.909Z,1568322681.909 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:11:23.497Z,1568322683.497 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:11:23.892Z,1568322683.892 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,210622.00,A,3648.17429,N,12147.28163,W,0.078,131.82,120919,,,A*72 2019-09-12T21:11:23.894Z,1568322683.894 [NAL9602](INFO): GPS fix at 20190912T210622: (36.802905, -121.788027) 2019-09-12T21:11:23.961Z,1568322683.961 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:11:23.961Z,1568322683.961 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:11:25.593Z,1568322685.593 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:11:31.640Z,1568322691.640 [DataOverHttps](INFO): Sending 63 bytes from file Logs/20190912T201420/Courier0033.lzma 2019-09-12T21:11:33.646Z,1568322693.646 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0033.lzma.bak 2019-09-12T21:11:33.646Z,1568322693.646 [DataOverHttps](INFO): SBD MOMSN=11777396 2019-09-12T21:11:50.629Z,1568322710.629 [DataOverHttps](INFO): Sending 118 bytes from file Logs/20190912T201420/Express0034.lzma 2019-09-12T21:11:52.634Z,1568322712.634 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0034.lzma.bak 2019-09-12T21:11:52.634Z,1568322712.634 [DataOverHttps](INFO): SBD MOMSN=11777400 2019-09-12T21:11:53.881Z,1568322713.881 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:11:53.881Z,1568322713.881 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:11:53.881Z,1568322713.881 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:16:18.479Z,1568322978.479 [NAL9602](INFO): SBD MO Status=2, MOMSN=16878, MT Status=2, MTMSN=0 2019-09-12T21:16:18.479Z,1568322978.479 [NAL9602](ERROR): Failed to initiate SBD session. Error code: 2 2019-09-12T21:16:26.151Z,1568322986.151 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T21:16:54.459Z,1568323014.459 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:16:54.459Z,1568323014.459 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:16:54.459Z,1568323014.459 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:16:54.459Z,1568323014.459 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:16:54.868Z,1568323014.868 [Default:CheckIn:D] Stopped 2019-09-12T21:16:54.868Z,1568323014.868 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:16:55.280Z,1568323015.280 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 92.468490 min 2019-09-12T21:16:55.280Z,1568323015.280 [Default:CheckIn:E] Stopped 2019-09-12T21:16:55.280Z,1568323015.280 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:16:55.280Z,1568323015.280 [Default:CheckIn] Stopped 2019-09-12T21:16:55.280Z,1568323015.280 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:16:55.281Z,1568323015.281 [Default:CheckIn](INFO): Running loop #17 2019-09-12T21:16:55.281Z,1568323015.281 [Default:CheckIn] Running Loop=17 2019-09-12T21:16:55.281Z,1568323015.281 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:16:55.281Z,1568323015.281 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:16:56.880Z,1568323016.880 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:16:57.261Z,1568323017.261 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211155.00,A,3648.16818,N,12147.28374,W,0.467,147.86,120919,,,A*70 2019-09-12T21:16:57.263Z,1568323017.263 [NAL9602](INFO): GPS fix at 20190912T211155: (36.802803, -121.788062) 2019-09-12T21:16:57.287Z,1568323017.287 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:16:57.287Z,1568323017.287 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:16:59.289Z,1568323019.289 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:17:04.624Z,1568323024.624 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190912T201420/Courier0036.lzma 2019-09-12T21:17:06.630Z,1568323026.630 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0036.lzma.bak 2019-09-12T21:17:06.630Z,1568323026.630 [DataOverHttps](INFO): SBD MOMSN=11777422 2019-09-12T21:17:23.545Z,1568323043.545 [DataOverHttps](INFO): Sending 219 bytes from file Logs/20190912T201420/Express0037.lzma 2019-09-12T21:17:25.554Z,1568323045.554 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0037.lzma.bak 2019-09-12T21:17:25.554Z,1568323045.554 [DataOverHttps](INFO): SBD MOMSN=11777426 2019-09-12T21:17:26.795Z,1568323046.795 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:17:26.795Z,1568323046.795 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:17:26.795Z,1568323046.795 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:17:30.002Z,1568323050.002 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:22:27.385Z,1568323347.385 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:22:27.385Z,1568323347.385 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:22:27.385Z,1568323347.385 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:22:27.385Z,1568323347.385 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:22:27.777Z,1568323347.777 [Default:CheckIn:D] Stopped 2019-09-12T21:22:27.777Z,1568323347.777 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 98.016984 min 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn:E] Stopped 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn] Stopped 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:22:28.181Z,1568323348.181 [Default:CheckIn](INFO): Running loop #18 2019-09-12T21:22:28.182Z,1568323348.182 [Default:CheckIn] Running Loop=18 2019-09-12T21:22:28.182Z,1568323348.182 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:22:28.182Z,1568323348.182 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:22:29.789Z,1568323349.789 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:22:30.190Z,1568323350.190 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,211727.00,A,3648.16542,N,12147.28032,W,0.661,139.24,120919,,,A*75 2019-09-12T21:22:30.192Z,1568323350.192 [NAL9602](INFO): GPS fix at 20190912T211727: (36.802757, -121.788005) 2019-09-12T21:22:30.216Z,1568323350.216 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:22:30.216Z,1568323350.216 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:22:31.810Z,1568323351.810 [NAL9602](ERROR): parseGSV uart error: serial buffer full 2019-09-12T21:22:37.548Z,1568323357.548 [DataOverHttps](INFO): Sending 64 bytes from file Logs/20190912T201420/Courier0039.lzma 2019-09-12T21:22:39.554Z,1568323359.554 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0039.lzma.bak 2019-09-12T21:22:39.554Z,1568323359.554 [DataOverHttps](INFO): SBD MOMSN=11777439 2019-09-12T21:22:56.600Z,1568323376.600 [DataOverHttps](INFO): Sending 120 bytes from file Logs/20190912T201420/Express0040.lzma 2019-09-12T21:22:58.606Z,1568323378.606 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0040.lzma.bak 2019-09-12T21:22:58.606Z,1568323378.606 [DataOverHttps](INFO): SBD MOMSN=11777446 2019-09-12T21:23:00.115Z,1568323380.115 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:23:00.115Z,1568323380.115 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:23:00.116Z,1568323380.116 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:27:32.368Z,1568323652.368 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2019-09-12T21:28:00.693Z,1568323680.693 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2019-09-12T21:28:00.693Z,1568323680.693 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:28:00.693Z,1568323680.693 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:28:00.693Z,1568323680.693 [Default:CheckIn:D] Running Loop=1 2019-09-12T21:28:01.077Z,1568323681.077 [Default:CheckIn:D] Stopped 2019-09-12T21:28:01.077Z,1568323681.077 [Default:CheckIn:E] Running Loop=1 2019-09-12T21:28:01.488Z,1568323681.488 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 103.571981 min 2019-09-12T21:28:01.488Z,1568323681.488 [Default:CheckIn:E] Stopped 2019-09-12T21:28:01.488Z,1568323681.488 [Default:CheckIn](INFO): Completed Default:CheckIn 2019-09-12T21:28:01.488Z,1568323681.488 [Default:CheckIn] Stopped 2019-09-12T21:28:01.488Z,1568323681.488 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:28:01.489Z,1568323681.489 [Default:CheckIn](INFO): Running loop #19 2019-09-12T21:28:01.489Z,1568323681.489 [Default:CheckIn] Running Loop=19 2019-09-12T21:28:01.489Z,1568323681.489 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2019-09-12T21:28:01.489Z,1568323681.489 [Default:CheckIn:Read_GPS] Running Loop=1 2019-09-12T21:28:03.088Z,1568323683.088 [NAL9602](DEBUG): Fix Requested 2019-09-12T21:28:03.500Z,1568323683.500 [NAL9602](DEBUG): Parsing RMC sentence: $GPRMC,212300.00,A,3648.18494,N,12147.29359,W,2.469,200.23,120919,,,A*7A 2019-09-12T21:28:03.502Z,1568323683.502 [NAL9602](INFO): GPS fix at 20190912T212300: (36.803082, -121.788226) 2019-09-12T21:28:03.526Z,1568323683.526 [Default:CheckIn:Read_GPS] Stopped 2019-09-12T21:28:03.526Z,1568323683.526 [Default:CheckIn:Read_Iridium] Running Loop=1 2019-09-12T21:28:10.660Z,1568323690.660 [DataOverHttps](INFO): Sending 62 bytes from file Logs/20190912T201420/Courier0042.lzma 2019-09-12T21:28:12.666Z,1568323692.666 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Courier0042.lzma.bak 2019-09-12T21:28:12.666Z,1568323692.666 [DataOverHttps](INFO): SBD MOMSN=11777477 2019-09-12T21:28:29.709Z,1568323709.709 [DataOverHttps](INFO): Sending 212 bytes from file Logs/20190912T201420/Express0043.lzma 2019-09-12T21:28:31.715Z,1568323711.715 [DataOverHttps](INFO): Moved sent file to Logs/20190912T201420/Express0043.lzma.bak 2019-09-12T21:28:31.715Z,1568323711.715 [DataOverHttps](INFO): SBD MOMSN=11777483 2019-09-12T21:28:32.000Z,1568323713.000 [Default:CheckIn:Read_Iridium] Stopped 2019-09-12T21:28:32.000Z,1568323713.000 [Default:CheckIn:C.Wait] Running Loop=1 2019-09-12T21:28:32.000Z,1568323713.000 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2019-09-12T21:28:35.798Z,1568323715.798 [NAL9602](INFO): Not Powering down - fast GPS 2019-09-12T21:30:49.193Z,1568323849.193 [CommandLine](IMPORTANT): got command quit 2019-09-12T21:30:50.201Z,1568323850.201 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:50.202Z,1568323850.202 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.285Z,1568323850.285 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup. Bye! 2019-09-12T21:30:50.285Z,1568323850.285 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.286Z,1568323850.286 [CommandLine](INFO): Join timeout helper Thread ID is 5749 2019-09-12T21:30:50.290Z,1568323850.290 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler 2019-09-12T21:30:50.290Z,1568323850.290 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.290Z,1568323850.290 [NavChartDb](INFO): Join timeout helper Thread ID is 5750 2019-09-12T21:30:50.645Z,1568323850.645 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:50.645Z,1568323850.645 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.665Z,1568323850.665 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler 2019-09-12T21:30:50.665Z,1568323850.665 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.665Z,1568323850.665 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 5751 2019-09-12T21:30:50.701Z,1568323850.701 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:50.702Z,1568323850.702 [WetLabsBB2FL](INFO): Powering down 2019-09-12T21:30:50.702Z,1568323850.702 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.705Z,1568323850.705 [ComponentRegistry](INFO): Shutting down CTD_Seabird ThreadHandler 2019-09-12T21:30:50.705Z,1568323850.705 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:50.705Z,1568323850.705 [CTD_Seabird](INFO): Join timeout helper Thread ID is 5752 2019-09-12T21:30:51.629Z,1568323851.629 [CTD_Seabird](INFO): Powering down 2019-09-12T21:30:51.641Z,1568323851.641 [CTD_Seabird ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:51.641Z,1568323851.641 [CTD_Seabird](INFO): Powering down 2019-09-12T21:30:51.653Z,1568323851.653 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:51.661Z,1568323851.661 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler 2019-09-12T21:30:51.661Z,1568323851.661 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:51.661Z,1568323851.661 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 5753 2019-09-12T21:30:51.721Z,1568323851.721 [CTD_NeilBrown](INFO): Powering down 2019-09-12T21:30:51.733Z,1568323851.733 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:51.733Z,1568323851.733 [CTD_NeilBrown](INFO): Powering down 2019-09-12T21:30:51.745Z,1568323851.745 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:51.762Z,1568323851.762 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler 2019-09-12T21:30:51.762Z,1568323851.762 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:51.762Z,1568323851.762 [Radio_Surface](INFO): Join timeout helper Thread ID is 5754 2019-09-12T21:30:52.129Z,1568323852.129 [Radio_Surface](INFO): Powering down 2019-09-12T21:30:52.130Z,1568323852.130 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:52.130Z,1568323852.130 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.149Z,1568323852.149 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler 2019-09-12T21:30:52.149Z,1568323852.149 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.150Z,1568323852.150 [DataOverHttps](INFO): Join timeout helper Thread ID is 5755 2019-09-12T21:30:52.549Z,1568323852.549 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:52.549Z,1568323852.549 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.553Z,1568323852.553 [ComponentRegistry](INFO): Shutting down logger ThreadHandler 2019-09-12T21:30:52.554Z,1568323852.554 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.554Z,1568323852.554 [logger](INFO): Join timeout helper Thread ID is 5756 2019-09-12T21:30:52.557Z,1568323852.557 [logger ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:52.557Z,1568323852.557 [logger ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.573Z,1568323852.573 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler 2019-09-12T21:30:52.573Z,1568323852.573 [CommandLine ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.574Z,1568323852.574 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler 2019-09-12T21:30:52.574Z,1568323852.574 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.574Z,1568323852.574 [controlThread](INFO): Join timeout helper Thread ID is 5757 2019-09-12T21:30:52.737Z,1568323852.737 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread. 2019-09-12T21:30:52.737Z,1568323852.737 [controlThread](DEBUG): Uninitializing ControlThread 2019-09-12T21:30:52.737Z,1568323852.737 [AHRS_M2](INFO): Powering down 2019-09-12T21:30:52.809Z,1568323852.809 [NAL9602](INFO): Powering down 2019-09-12T21:30:52.811Z,1568323852.811 [Aanderaa_O2](INFO): Powering down 2019-09-12T21:30:52.813Z,1568323852.813 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator. 2019-09-12T21:30:52.814Z,1568323852.814 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator. 2019-09-12T21:30:52.814Z,1568323852.814 [NavChart](DEBUG): Uninitialize NavChart Navigation. 2019-09-12T21:30:52.815Z,1568323852.815 [MissionManager](INFO): Uninitializing Mission Default 2019-09-12T21:30:52.815Z,1568323852.815 [Default] Stopped 2019-09-12T21:30:52.815Z,1568323852.815 [Default](DEBUG): Aggregate::uninitialize Default 2019-09-12T21:30:52.815Z,1568323852.815 [Default:B.GoToSurface] Stopped 2019-09-12T21:30:52.815Z,1568323852.815 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2019-09-12T21:30:52.815Z,1568323852.815 [Default:CheckIn] Stopped 2019-09-12T21:30:52.815Z,1568323852.815 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2019-09-12T21:30:52.815Z,1568323852.815 [Default:CheckIn:C.Wait] Stopped 2019-09-12T21:30:52.815Z,1568323852.815 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2019-09-12T21:30:52.818Z,1568323852.818 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent. 2019-09-12T21:30:52.818Z,1568323852.818 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent. 2019-09-12T21:30:52.818Z,1568323852.818 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent. 2019-09-12T21:30:52.819Z,1568323852.819 [LoopControl](DEBUG): Uninitialize LoopControlComponent. 2019-09-12T21:30:52.819Z,1568323852.819 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo. 2019-09-12T21:30:52.819Z,1568323852.819 [BuoyancyServo](INFO): Powering down 2019-09-12T21:30:52.833Z,1568323852.833 [ElevatorServo](DEBUG): Uninitialize Elevator Servo. 2019-09-12T21:30:52.833Z,1568323852.833 [ElevatorServo](INFO): Powering down 2019-09-12T21:30:52.834Z,1568323852.834 [MassServo](DEBUG): Uninitialize Mass Servo. 2019-09-12T21:30:52.834Z,1568323852.834 [MassServo](INFO): Powering down 2019-09-12T21:30:52.835Z,1568323852.835 [RudderServo](DEBUG): Uninitialize Rudder Servo. 2019-09-12T21:30:52.835Z,1568323852.835 [RudderServo](INFO): Powering down 2019-09-12T21:30:52.835Z,1568323852.835 [ThrusterServo](DEBUG): Uninitialize Thruster Servo. 2019-09-12T21:30:52.836Z,1568323852.836 [ThrusterServo](INFO): Powering down 2019-09-12T21:30:52.836Z,1568323852.836 [SBIT](DEBUG): Uninitialize SBIT Component. 2019-09-12T21:30:52.837Z,1568323852.837 [IBIT](DEBUG): Uninitialize IBIT Component. 2019-09-12T21:30:52.837Z,1568323852.837 [CBIT](DEBUG): Uninitialize CBIT Component. 2019-09-12T21:30:52.837Z,1568323852.837 [CBIT](DEBUG): Powering off loads. 2019-09-12T21:30:52.848Z,1568323852.848 [CBIT](DEBUG): Disabling WDT. 2019-09-12T21:30:52.860Z,1568323852.860 [CBIT](DEBUG): Opening all GF detection circuits. 2019-09-12T21:30:52.861Z,1568323852.861 [controlThread ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.955Z,1568323852.955 [Radio_Surface ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.961Z,1568323852.961 [DataOverHttps ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.996Z,1568323852.996 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:52.999Z,1568323852.999 [CTD_Seabird ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:53.002Z,1568323853.002 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:53.041Z,1568323853.041 [NavChartDb ThreadHandler](INFO): Thread cancelled. 2019-09-12T21:30:53.145Z,1568323853.145 [logger ThreadHandler](INFO): Thread cancelled.