2021-08-03T13:31:46.457Z,1627997506.457 [CommandLine](IMPORTANT): got command restart logs 2021-08-03T13:35:59.435Z,1627997759.435 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-08-03T13:35:59.435Z,1627997759.435 [Default:CheckIn:C.Wait] Stopped 2021-08-03T13:35:59.435Z,1627997759.435 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-08-03T13:35:59.435Z,1627997759.435 [Default:CheckIn:D] Running Loop=1 2021-08-03T13:35:59.837Z,1627997759.837 [Default:CheckIn:D] Stopped 2021-08-03T13:35:59.837Z,1627997759.837 [Default:CheckIn:E] Running Loop=1 2021-08-03T13:36:00.234Z,1627997760.234 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 10.978227 min 2021-08-03T13:36:00.234Z,1627997760.234 [Default:CheckIn:E] Stopped 2021-08-03T13:36:00.234Z,1627997760.234 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn] Stopped 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn](INFO): Running loop #2 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn] Running Loop=2 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-08-03T13:36:00.235Z,1627997760.235 [Default:CheckIn:Read_GPS] Running Loop=1 2021-08-03T13:36:01.837Z,1627997761.837 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-08-03T13:36:01.837Z,1627997761.837 [NAL9602] Data Fault, FailCount= 2 2021-08-03T13:36:01.837Z,1627997761.837 [NAL9602](ERROR): Data Fault 2021-08-03T13:36:01.910Z,1627997761.910 [CBIT](ERROR): Data Fault in component: NAL9602 2021-08-03T13:36:02.251Z,1627997762.251 [NAL9602](INFO): Powering down 2021-08-03T13:36:03.075Z,1627997763.075 [CBIT](INFO): Clearing failed state for component NAL9602 2021-08-03T13:36:03.075Z,1627997763.075 [NAL9602] No Fault, FailCount= 2 2021-08-03T13:36:32.587Z,1627997792.587 [NAL9602](INFO): Powering up NAL9602 2021-08-03T13:36:43.462Z,1627997803.462 [NAL9602](INFO): NAL9602 initialized 2021-08-03T13:38:47.131Z,1627997927.131 [DVL_micro](ERROR): Failed to parse: :T00000000,35.0,+22.4,0000.0,1489.0,000 2021-08-03T13:41:00.580Z,1627998060.580 [Default:CheckIn:Read_GPS](INFO): Timed out from 2021-08-03T13:36:00.2Z 2021-08-03T13:41:00.580Z,1627998060.580 [Default:CheckIn:Read_GPS] Stopped 2021-08-03T13:41:00.580Z,1627998060.580 [Default:CheckIn:Read_Iridium] Running Loop=1 2021-08-03T13:41:08.035Z,1627998068.035 [DataOverHttps](INFO): Sending 39 bytes from file Logs/20210803T130835/Courier0016.lzma 2021-08-03T13:41:09.038Z,1627998069.038 [DataOverHttps](INFO): Moved sent file to Logs/20210803T130835/Courier0016.lzma.bak 2021-08-03T13:41:09.038Z,1627998069.038 [DataOverHttps](INFO): SBD MOMSN=15800374 2021-08-03T13:41:24.804Z,1627998084.804 [DataOverHttps](INFO): Sending 150 bytes from file Logs/20210803T133146/Courier0000.lzma 2021-08-03T13:41:25.806Z,1627998085.806 [DataOverHttps](INFO): Moved sent file to Logs/20210803T133146/Courier0000.lzma.bak 2021-08-03T13:41:25.806Z,1627998085.806 [DataOverHttps](INFO): SBD MOMSN=15800376 2021-08-03T13:41:45.260Z,1627998105.260 [DataOverHttps](INFO): Sending 187 bytes from file Logs/20210803T130835/Express0017.lzma 2021-08-03T13:41:46.262Z,1627998106.262 [DataOverHttps](INFO): Moved sent file to Logs/20210803T130835/Express0017.lzma.bak 2021-08-03T13:41:46.262Z,1627998106.262 [DataOverHttps](INFO): SBD MOMSN=15800379 2021-08-03T13:41:47.049Z,1627998107.049 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-08-03T13:42:04.876Z,1627998124.876 [DataOverHttps](INFO): Sending 429 bytes from file Logs/20210803T133146/Express0001.lzma 2021-08-03T13:42:05.878Z,1627998125.878 [DataOverHttps](INFO): Moved sent file to Logs/20210803T133146/Express0001.lzma.bak 2021-08-03T13:42:05.878Z,1627998125.878 [DataOverHttps](INFO): SBD MOMSN=15800383 2021-08-03T13:42:17.828Z,1627998137.828 [NAL9602](INFO): Not Powering down - fast GPS 2021-08-03T13:42:21.743Z,1627998141.743 [DataOverHttps](INFO): Sending 61 bytes from file Logs/20210803T133146/Express0004.lzma 2021-08-03T13:42:22.746Z,1627998142.746 [DataOverHttps](INFO): Moved sent file to Logs/20210803T133146/Express0004.lzma.bak 2021-08-03T13:42:22.746Z,1627998142.746 [DataOverHttps](INFO): SBD MOMSN=15800388 2021-08-03T13:42:24.294Z,1627998144.294 [Default:CheckIn:Read_Iridium] Stopped 2021-08-03T13:42:24.295Z,1627998144.295 [Default:CheckIn:C.Wait] Running Loop=1 2021-08-03T13:42:24.295Z,1627998144.295 [Default:CheckIn:C.Wait](DEBUG): Initialize Wait Component. 2021-08-03T13:43:56.809Z,1627998236.809 [DVL_micro](ERROR): only read 3 of 4 data items 2021-08-03T13:43:56.809Z,1627998236.809 [DVL_micro](ERROR): Failed to parse: :RD,+9999.99,+9999.99,+9999.999 2021-08-03T13:44:32.354Z,1627998272.354 [DVL_micro](ERROR): only read 0 of 1 data item for BIT error 2021-08-03T13:44:32.355Z,1627998272.355 [DVL_micro](ERROR): Failed to parse: :TS,00000000000000,35.0,+22.6,0000.0,00 2021-08-03T13:47:24.891Z,1627998444.891 [Default:CheckIn:C.Wait](INFO): Done Waiting. 2021-08-03T13:47:24.891Z,1627998444.891 [Default:CheckIn:C.Wait] Stopped 2021-08-03T13:47:24.891Z,1627998444.891 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component. 2021-08-03T13:47:24.892Z,1627998444.892 [Default:CheckIn:D] Running Loop=1 2021-08-03T13:47:25.297Z,1627998445.297 [Default:CheckIn:D] Stopped 2021-08-03T13:47:25.297Z,1627998445.297 [Default:CheckIn:E] Running Loop=1 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn:E](IMPORTANT): Default mission has been running for 22.402570 min 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn:E] Stopped 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn](INFO): Completed Default:CheckIn 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn] Stopped 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn](INFO): Running loop #3 2021-08-03T13:47:25.686Z,1627998445.686 [Default:CheckIn] Running Loop=3 2021-08-03T13:47:25.687Z,1627998445.687 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-08-03T13:47:25.687Z,1627998445.687 [Default:CheckIn:Read_GPS] Running Loop=1 2021-08-03T13:47:27.289Z,1627998447.289 [NAL9602](FAULT): GPS failed to acquire within timeout. 2021-08-03T13:47:27.289Z,1627998447.289 [NAL9602] Data Fault, FailCount= 3 2021-08-03T13:47:27.289Z,1627998447.289 [NAL9602](ERROR): Data Fault 2021-08-03T13:47:27.308Z,1627998447.308 [CBIT](ERROR): Data Fault in component: NAL9602 2021-08-03T13:47:27.711Z,1627998447.711 [NAL9602](INFO): Powering down 2021-08-03T13:47:28.544Z,1627998448.544 [CBIT](INFO): Clearing failed state for component NAL9602 2021-08-03T13:47:28.544Z,1627998448.544 [NAL9602] No Fault, FailCount= 3 2021-08-03T13:47:58.011Z,1627998478.011 [NAL9602](INFO): Powering up NAL9602 2021-08-03T13:48:08.907Z,1627998488.907 [NAL9602](INFO): NAL9602 initialized 2021-08-03T13:48:37.377Z,1627998517.377 [DataOverHttps](IMPORTANT): SBD MTMSN=20210803T134732 2021-08-03T13:48:44.915Z,1627998524.915 [DataOverHttps](INFO): Received command:load Maintenance/sample_lab.xml;set sample_lab.CartridgeType -1 count;run 2021-08-03T13:48:44.934Z,1627998524.934 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample_lab.xml 2021-08-03T13:48:44.934Z,1627998524.934 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample_lab.xml 2021-08-03T13:48:44.966Z,1627998524.966 [MissionManager](INFO): DefineArg sample_lab.MissionTimeout = 90.000000 min 2021-08-03T13:48:44.972Z,1627998524.972 [MissionManager](INFO): DefineArg sample_lab.CartridgeType = -4.000000 count 2021-08-03T13:48:44.974Z,1627998524.974 [MissionManager](INFO): DefineArg sample_lab.NumberOfSamples = 1.000000 count 2021-08-03T13:48:44.975Z,1627998524.975 [sample_lab:A.AbortSample](DEBUG): Construct. 2021-08-03T13:48:44.990Z,1627998524.990 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](DEBUG): Construct. 2021-08-03T13:48:44.999Z,1627998524.999 [MissionManager](DEBUG): This mission is designed to run in the lab only and triggers an ESP sample with specified type. How long to let the mission run. 90 Specifies ESP cartridge type code (defaults to archiveHiBiomass_bac: -4) -4 Number of samples to take. 1 Sampling ESP cartridge type 2021-08-03T13:48:45.004Z,1627998525.004 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample_lab.xml 2021-08-03T13:48:46.728Z,1627998526.728 [CommandLine](IMPORTANT): got command set sample_lab.CartridgeType -1.000000 count 2021-08-03T13:48:46.729Z,1627998526.729 [CommandLine](IMPORTANT): got command run 2021-08-03T13:48:46.730Z,1627998526.730 [CommandLine](IMPORTANT): Running 2021-08-03T13:48:46.916Z,1627998526.916 [Default] Stopped 2021-08-03T13:48:46.916Z,1627998526.916 [Default](DEBUG): Aggregate::uninitialize Default 2021-08-03T13:48:46.916Z,1627998526.916 [Default:B.GoToSurface] Stopped 2021-08-03T13:48:46.916Z,1627998526.916 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent. 2021-08-03T13:48:46.916Z,1627998526.916 [Default:CheckIn] Stopped 2021-08-03T13:48:46.916Z,1627998526.916 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn 2021-08-03T13:48:46.917Z,1627998526.917 [Default:CheckIn:Read_GPS] Stopped 2021-08-03T13:48:46.917Z,1627998526.917 [MissionManager](IMPORTANT): Started mission sample_lab 2021-08-03T13:48:46.917Z,1627998526.917 [sample_lab] Running Loop=1 2021-08-03T13:48:46.917Z,1627998526.917 [sample_lab](DEBUG): Aggregate::initialize sample_lab 2021-08-03T13:48:46.917Z,1627998526.917 [sample_lab:A.AbortSample] Running Loop=1 2021-08-03T13:48:46.917Z,1627998526.917 [sample_lab:A.AbortSample](INFO): Initializing AbortSample. 2021-08-03T13:48:46.918Z,1627998526.918 [sample_lab:SampleRepeater] Running Loop=1 2021-08-03T13:48:46.918Z,1627998526.918 [sample_lab:SampleRepeater](DEBUG): Aggregate::initialize sample_lab:SampleRepeater 2021-08-03T13:48:46.918Z,1627998526.918 [sample_lab:SampleRepeater:A] Running Loop=1 2021-08-03T13:48:46.919Z,1627998526.919 [sample_lab:SampleRepeater:A](IMPORTANT): Sampling ESP cartridge type -1.000000 count 2021-08-03T13:48:46.919Z,1627998526.919 [sample_lab:SampleRepeater:A] Stopped 2021-08-03T13:48:46.919Z,1627998526.919 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Running Loop=1 2021-08-03T13:48:46.919Z,1627998526.919 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Initializing ESPCartridgeSelect. 2021-08-03T13:48:46.919Z,1627998526.919 [sample_lab:A.AbortSample] Running Loop=1 2021-08-03T13:48:47.316Z,1627998527.316 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Issuing request for ESP cartridge type: -1. 2021-08-03T13:48:47.316Z,1627998527.316 [sample_lab:SampleRepeater:B.ESPCartridgeSelect] Stopped 2021-08-03T13:48:47.317Z,1627998527.317 [sample_lab:SampleRepeater:B.ESPCartridgeSelect](INFO): Uninitializing ESPCartridgeSelect. 2021-08-03T13:48:47.317Z,1627998527.317 [sample_lab:SampleRepeater:TriggerESP] Running Loop=1 2021-08-03T13:48:47.709Z,1627998527.709 [sample_lab:SampleRepeater:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling 2021-08-03T13:48:48.477Z,1627998528.477 [ESPComponent](DEBUG): (612) Will wait for 10.0000 before power-up/connection sequence 2021-08-03T13:48:58.577Z,1627998538.577 [ESPComponent](DEBUG): (612) Done with wait. Will continue with general power-up/connection sequence 2021-08-03T13:48:58.649Z,1627998538.649 [ESPComponent](INFO): powering up ESP 2021-08-03T13:48:58.668Z,1627998538.668 [ESPComponent](INFO): powering up ESP secondary power supply 2021-08-03T13:48:58.686Z,1627998538.686 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.5.2:10.89.5.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8 2021-08-03T13:48:58.804Z,1627998538.804 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000) 2021-08-03T13:48:59.044Z,1627998539.044 [ESPComponent](INFO): console: 2021-08-03T13:48:59.791Z,1627998539.791 [ESPComponent](INFO): console: 2021-08-03T13:49:00.194Z,1627998540.194 [ESPComponent](INFO): console:NAND: 256 MiB 2021-08-03T13:49:00.598Z,1627998540.598 [ESPComponent](INFO): console: BOOTMODE: SPI 2021-08-03T13:49:01.002Z,1627998541.002 [ESPComponent](INFO): console: reading SPI NOR..Done 2021-08-03T13:49:01.406Z,1627998541.406 [ESPComponent](INFO): console: 2021-08-03T13:49:01.809Z,1627998541.809 [ESPComponent](INFO): console: 2021-08-03T13:49:02.215Z,1627998542.215 [ESPComponent](INFO): console: U-Boot 2009.11-mbariD (Oct 20 2020 - 11:20:51) 2021-08-03T13:49:02.618Z,1627998542.618 [ESPComponent](INFO): console: 2021-08-03T13:49:03.022Z,1627998543.022 [ESPComponent](INFO): console: MBARI LPC31xx ESP 3G 2021-08-03T13:49:03.428Z,1627998543.428 [ESPComponent](INFO): console: flash params are already written into flash 2021-08-03T13:49:03.830Z,1627998543.830 [ESPComponent](INFO): console: DRAM: 64 MB 2021-08-03T13:49:04.234Z,1627998544.234 [ESPComponent](INFO): console: In: serial 2021-08-03T13:49:04.638Z,1627998544.638 [ESPComponent](INFO): console: Out: serial 2021-08-03T13:49:05.042Z,1627998545.042 [ESPComponent](INFO): console: Err: serial 2021-08-03T13:49:05.446Z,1627998545.446 [ESPComponent](INFO): console: Net: ks8851_mll 2021-08-03T13:49:05.851Z,1627998545.851 [ESPComponent](INFO): console: Hit to stop autoboot: 1  0 2021-08-03T13:49:06.254Z,1627998546.254 [ESPComponent](INFO): console: 4096 KiB S25FL032P at 0:0 is now current device 2021-08-03T13:49:06.658Z,1627998546.658 [ESPComponent](INFO): console: Loading kernel from SPI flash...done 2021-08-03T13:49:07.063Z,1627998547.063 [ESPComponent](INFO): console: ## Booting kernel from Legacy Image at 31000000 ... 2021-08-03T13:49:07.474Z,1627998547.474 [ESPComponent](INFO): console: Image Name: Linux-2.6.33-ea3131-mbari7 2021-08-03T13:49:07.871Z,1627998547.871 [ESPComponent](INFO): console: Image Type: ARM Linux Kernel Image (uncompressed) 2021-08-03T13:49:08.275Z,1627998548.275 [ESPComponent](INFO): console: Data Size: 1681728 Bytes = 1.6 MB 2021-08-03T13:49:08.678Z,1627998548.678 [ESPComponent](INFO): console: Load Address: 30008000 2021-08-03T13:49:09.082Z,1627998549.082 [ESPComponent](INFO): console: Entry Point: 30008000 2021-08-03T13:49:09.487Z,1627998549.487 [ESPComponent](INFO): console: Verifying Checksum ... OK 2021-08-03T13:49:09.891Z,1627998549.891 [ESPComponent](INFO): console: Loading Kernel Image ... OK 2021-08-03T13:49:10.293Z,1627998550.293 [ESPComponent](INFO): console: OK 2021-08-03T13:49:10.698Z,1627998550.698 [ESPComponent](INFO): console: 2021-08-03T13:49:11.102Z,1627998551.102 [ESPComponent](INFO): console: Starting kernel ... 2021-08-03T13:49:11.506Z,1627998551.506 [ESPComponent](INFO): console: 2021-08-03T13:49:11.913Z,1627998551.913 [ESPComponent](INFO): console: Uncompressing Linux... done, booting the kernel. 2021-08-03T13:49:12.315Z,1627998552.315 [ESPComponent](INFO): console: [ 0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177 2021-08-03T13:49:12.719Z,1627998552.719 [ESPComponent](INFO): console: [ 0.00] CPU: VIVT data cache, VIVT instruction cache 2021-08-03T13:49:13.123Z,1627998553.123 [ESPComponent](INFO): console: [ 0.00] Machine: NXP EA313X 2021-08-03T13:49:13.527Z,1627998553.527 [ESPComponent](INFO): console: [ 0.00] Memory policy: ECC disabled, Data cache writeback 2021-08-03T13:49:13.931Z,1627998553.931 [ESPComponent](INFO): console: [ 0.00] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 16256 2021-08-03T13:49:14.335Z,1627998554.335 [ESPComponent](INFO): console: [ 0.24] Mount-cache hash table entries: 512 2021-08-03T13:49:14.738Z,1627998554.738 [ESPComponent](INFO): console: [ 0.29] MBARI ESP 3G 2021-08-03T13:49:15.142Z,1627998555.142 [ESPComponent](INFO): console: [ 0.39] bio: create slab at 0 2021-08-03T13:49:15.548Z,1627998555.548 [ESPComponent](INFO): console: [ 0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2021-08-03T13:49:15.951Z,1627998555.951 [ESPComponent](INFO): console: [ 0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2021-08-03T13:49:16.355Z,1627998556.355 [ESPComponent](INFO): console: [ 0.50] i2c i2c-0: Master timed out. st0, cntrl = 000e. Resetting master... 2021-08-03T13:49:16.760Z,1627998556.760 [ESPComponent](INFO): console: [ 0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2021-08-03T13:49:17.163Z,1627998557.163 [ESPComponent](INFO): console: [ 0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2021-08-03T13:49:17.567Z,1627998557.567 [ESPComponent](INFO): console: [ 0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master... 2021-08-03T13:49:17.971Z,1627998557.971 [ESPComponent](INFO): console: [ 0.56] NetWinder Floating Point Emulator V0.97 (double precision) 2021-08-03T13:49:18.374Z,1627998558.374 [ESPComponent](INFO): console: [ 0.58] yaffs Aug 4 2020 18:36:40 Installing. 2021-08-03T13:49:18.778Z,1627998558.778 [ESPComponent](INFO): console: [ 0.72] m25p80 spi0.3: m25p80 found s25sl032a flash 2021-08-03T13:49:19.183Z,1627998559.183 [ESPComponent](INFO): console: [ 1.02] yaffs: Attempting MTD mount on 31.2, "mtdblock2" 2021-08-03T13:49:19.586Z,1627998559.586 [ESPComponent](INFO): console: [ 1.03] yaffs: auto selecting yaffs2 2021-08-03T13:49:19.990Z,1627998559.990 [ESPComponent](INFO): console: [ 1.24] block 2044 is bad 2021-08-03T13:49:20.395Z,1627998560.395 [ESPComponent](INFO): console: [ 1.24] block 2045 is bad 2021-08-03T13:49:20.798Z,1627998560.798 [ESPComponent](INFO): console: [ 1.24] block 2046 is bad 2021-08-03T13:49:21.202Z,1627998561.202 [ESPComponent](INFO): console: [ 1.25] block 2047 is bad 2021-08-03T13:49:21.607Z,1627998561.607 [ESPComponent](INFO): console: [ 4.71] yaffs_read_super: isCheckpointed 0 2021-08-03T13:49:22.011Z,1627998562.011 [ESPComponent](INFO): console: [ 4.71] VFS: Mounted root (yaffs filesystem) readonly on device 31:2. 2021-08-03T13:49:22.413Z,1627998562.413 [ESPComponent](INFO): console: 2021-08-03T13:49:22.818Z,1627998562.818 [ESPComponent](INFO): console:INIT: version 2.85 booting 2021-08-03T13:49:23.222Z,1627998563.222 [ESPComponent](INFO): console: 2021-08-03T13:49:23.627Z,1627998563.627 [ESPComponent](INFO): console:MBARI ESP Embedded Linux http://www.mbari.org mailto:brent@mbari.org 2021-08-03T13:49:24.030Z,1627998564.030 [ESPComponent](INFO): console: ESPmv1 2021-08-03T13:49:24.434Z,1627998564.434 [ESPComponent](INFO): console: 2021-08-03T13:49:24.838Z,1627998564.838 [ESPComponent](INFO): console:INIT: Entering runlevel: 3 2021-08-03T13:49:25.242Z,1627998565.242 [ESPComponent](INFO): console: 2021-08-03T13:49:25.647Z,1627998565.647 [ESPComponent](INFO): console:Loading kernel modules 2021-08-03T13:49:26.051Z,1627998566.051 [ESPComponent](INFO): console: Mounting filesystems and adding swapfiles listed in /etc/fstab 2021-08-03T13:49:26.455Z,1627998566.455 [ESPComponent](INFO): console: Starting device events handler 2021-08-03T13:49:26.858Z,1627998566.858 [ESPComponent](INFO): console: Set system clock to: Tue Aug 3 09:48:27 EDT 2021 2021-08-03T13:49:27.262Z,1627998567.262 [ESPComponent](INFO): console: Starting syslogd klogd... 2021-08-03T13:49:27.666Z,1627998567.666 [ESPComponent](INFO): console: stopped syslogd (pid 620) 2021-08-03T13:49:28.070Z,1627998568.070 [ESPComponent](INFO): console: Bringing up lo ... 2021-08-03T13:49:28.474Z,1627998568.474 [ESPComponent](INFO): console: lo IP=127.0.0.1 2021-08-03T13:49:28.878Z,1627998568.878 [ESPComponent](INFO): console: Packet forwarding enabled 2021-08-03T13:49:29.282Z,1627998569.282 [ESPComponent](INFO): console: Bringing up platform ... 2021-08-03T13:49:29.686Z,1627998569.686 [ESPComponent](INFO): console: Starting portmap... 2021-08-03T13:49:30.091Z,1627998570.091 [ESPComponent](INFO): console: Network unavailable: Local time is Tue Aug 3 09:48:29 EDT 2021 2021-08-03T13:49:30.494Z,1627998570.494 [ESPComponent](INFO): console: Starting thttpd... 2021-08-03T13:49:30.898Z,1627998570.898 [ESPComponent](INFO): console: Starting dnsmasq... 2021-08-03T13:49:31.302Z,1627998571.302 [ESPComponent](INFO): console: Bringing up wired ... 2021-08-03T13:49:31.707Z,1627998571.707 [ESPComponent](INFO): console: Determining IP configuration for wired ...udhcpc (v1.11.2) started 2021-08-03T13:49:32.109Z,1627998572.109 [ESPComponent](INFO): console: 2021-08-03T13:49:32.514Z,1627998572.514 [ESPComponent](INFO): console: 2021-08-03T13:49:32.919Z,1627998572.919 [ESPComponent](INFO): console:MBARI ESP Embedded Linux 2.65 -- 10/9/20 brent@mbari.org 2021-08-03T13:49:33.321Z,1627998573.321 [ESPComponent](INFO): console: 2021-08-03T13:49:33.727Z,1627998573.727 [ESPComponent](INFO): console:ESPmv1 login: Sending discover... 2021-08-03T13:49:34.130Z,1627998574.130 [ESPComponent](INFO): console: Sending discover... 2021-08-03T13:49:34.534Z,1627998574.534 [ESPComponent](INFO): console: Sending discover... 2021-08-03T13:49:34.000Z,1627998575.000 [ESPComponent](INFO): console: 2021-08-03T13:49:36.958Z,1627998576.958 [ESPComponent](INFO): console:No lease, forking to background 2021-08-03T13:49:37.367Z,1627998577.367 [ESPComponent](INFO): console: Bringing up direct ... 2021-08-03T13:49:37.832Z,1627998577.832 [ESPComponent](INFO): console: direct IP=10.10.10.10 2021-08-03T13:49:38.236Z,1627998578.236 [ESPComponent](INFO): console: 2021-08-03T13:49:44.658Z,1627998584.658 [ESPComponent](IMPORTANT): ESP has connected as client 2021-08-03T13:49:45.498Z,1627998585.498 [ESPComponent](IMPORTANT): [sample #2] Setting cartridge argument to -1 2021-08-03T13:49:45.498Z,1627998585.498 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT 2021-08-03T13:49:45.499Z,1627998585.499 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2 2021-08-03T13:49:45.625Z,1627998585.625 [sample_lab:SampleRepeater:TriggerESP] Stopped 2021-08-03T13:49:45.625Z,1627998585.625 [sample_lab:SampleRepeater:WaitForESP] Running Loop=1 2021-08-03T13:49:45.990Z,1627998585.990 [sample_lab:SampleRepeater:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number 2021-08-03T13:49:46.290Z,1627998586.290 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_LOG (@100.0) 2021-08-03T13:49:46.698Z,1627998586.698 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PREPARING_SHOW_STATUS (@100.0) 2021-08-03T13:49:48.726Z,1627998588.726 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_LOADING_CARTRIDGE (@100.0) 2021-08-03T13:50:23.066Z,1627998623.066 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_WAITING_FOR_PRIMING (@60,aRNAl_bac) 2021-08-03T13:50:24.682Z,1627998624.682 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_PRIMING (@100.0) 2021-08-03T13:50:25.087Z,1627998625.087 [ESPComponent](FAULT): In S_PRIMING: Couldn't parse filtering timeout expected from ESP. Got result: :FILTERING 2021-08-03T13:50:25.088Z,1627998625.088 [ESPComponent](IMPORTANT): Syncing ESP logs with command: rsync -azPq --timeout=60 esp@esp:'/var/log/esp/real /var/log/esp/real.out /var/log/esp/real.slot /var/log/esp/*.spr' /LRAUV/ESPlogs & 2021-08-03T13:50:25.122Z,1627998625.122 [ESPComponent](INFO): closing pipe. 2021-08-03T13:50:25.490Z,1627998625.490 [ESPComponent](IMPORTANT): [sample #2] ESP sampling state: S_ERROR (@100.0) 2021-08-03T13:50:49.099Z,1627998649.099 [CommandLine](IMPORTANT): got command failComponent 2021-08-03T13:50:49.099Z,1627998649.099 [CommandLine](IMPORTANT): Failed components: 2021-08-03T13:50:49.100Z,1627998649.100 [CommandLine](IMPORTANT): No failed Components. 2021-08-03T13:50:50.735Z,1627998650.735 [CommandLine](IMPORTANT): got command show stack 2021-08-03T13:50:50.735Z,1627998650.735 [CommandLine](IMPORTANT): Behavior Stack: 2021-08-03T13:50:50.737Z,1627998650.737 [sample_lab](IMPORTANT): Priority 0: sample_lab:A.AbortSample 2021-08-03T13:50:50.738Z,1627998650.738 [sample_lab:SampleRepeater](IMPORTANT): Priority 1: sample_lab:SampleRepeater:WaitForESP 2021-08-03T13:52:44.299Z,1627998764.299 [CommandLine](IMPORTANT): got command failComponent 2021-08-03T13:52:44.299Z,1627998764.299 [CommandLine](IMPORTANT): Failed components: 2021-08-03T13:52:44.299Z,1627998764.299 [CommandLine](IMPORTANT): No failed Components. 2021-08-03T13:53:12.432Z,1627998792.432 [NAL9602](FAULT): MT Queue status failed to be acquired within timeout. Will not retry this session. 2021-08-03T13:53:43.120Z,1627998823.120 [NAL9602](INFO): Not Powering down - fast GPS 2021-08-03T13:54:15.912Z,1627998855.912 [DVL_micro](ERROR): Failed to parse: :SA,-03.21,-01.02,014.3 2021-08-03T13:55:25.378Z,1627998925.378 [ESPComponent](IMPORTANT): [sample #2] ESP sampling sequence completed normally. 2021-08-03T13:55:25.379Z,1627998925.379 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=2 2021-08-03T13:55:25.406Z,1627998925.406 [sample_lab:SampleRepeater:WaitForESP] Stopped 2021-08-03T13:55:25.406Z,1627998925.406 [sample_lab:SampleRepeater](INFO): Completed sample_lab:SampleRepeater 2021-08-03T13:55:25.406Z,1627998925.406 [sample_lab:SampleRepeater] Stopped 2021-08-03T13:55:25.406Z,1627998925.406 [sample_lab:SampleRepeater](DEBUG): Aggregate::uninitialize sample_lab:SampleRepeater 2021-08-03T13:55:25.406Z,1627998925.406 [sample_lab](INFO): Completed sample_lab 2021-08-03T13:55:25.407Z,1627998925.407 [MissionManager](INFO): sample_lab is completed. 2021-08-03T13:55:25.407Z,1627998925.407 [MissionManager](INFO): Uninitializing Mission sample_lab 2021-08-03T13:55:25.407Z,1627998925.407 [sample_lab] Stopped 2021-08-03T13:55:25.407Z,1627998925.407 [sample_lab](DEBUG): Aggregate::uninitialize sample_lab 2021-08-03T13:55:25.407Z,1627998925.407 [sample_lab:A.AbortSample] Stopped 2021-08-03T13:55:25.407Z,1627998925.407 [sample_lab:A.AbortSample](INFO): Uninitializing AbortSample. 2021-08-03T13:55:25.783Z,1627998925.783 [ESPComponent](IMPORTANT): [sample #2] ESP log summary report (1 messages): @09:49:58.56 Selecting Cartridge 60 2021-08-03T13:55:25.784Z,1627998925.784 [ESPComponent](INFO): powering down ESP 2021-08-03T13:55:25.785Z,1627998925.785 [ESPComponent](INFO): powering down ESP secondary power supply 2021-08-03T13:55:25.952Z,1627998925.952 [MissionManager](IMPORTANT): Started mission Default 2021-08-03T13:55:25.952Z,1627998925.952 [Default] Running Loop=1 2021-08-03T13:55:25.952Z,1627998925.952 [Default](DEBUG): Aggregate::initialize Default 2021-08-03T13:55:25.953Z,1627998925.953 [Default:B.GoToSurface] Running Loop=1 2021-08-03T13:55:25.953Z,1627998925.953 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent. 2021-08-03T13:55:25.953Z,1627998925.953 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s. 2021-08-03T13:55:25.953Z,1627998925.953 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees. 2021-08-03T13:55:25.954Z,1627998925.954 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s. 2021-08-03T13:55:25.954Z,1627998925.954 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds. 2021-08-03T13:55:25.954Z,1627998925.954 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds. 2021-08-03T13:55:25.955Z,1627998925.955 [Default:A.Wait] Running Loop=1 2021-08-03T13:55:25.955Z,1627998925.955 [Default:A.Wait](DEBUG): Initialize Wait Component. 2021-08-03T13:55:39.158Z,1627998939.158 [Default:A.Wait](INFO): Done Waiting. 2021-08-03T13:55:39.158Z,1627998939.158 [Default:A.Wait] Stopped 2021-08-03T13:55:39.158Z,1627998939.158 [Default:A.Wait](DEBUG): Uninitialize Wait Component. 2021-08-03T13:55:39.597Z,1627998939.597 [Default:CheckIn] Running Loop=1 2021-08-03T13:55:39.597Z,1627998939.597 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn 2021-08-03T13:55:39.597Z,1627998939.597 [Default:CheckIn:Read_GPS] Running Loop=1 2021-08-03T13:56:12.339Z,1627998972.339 [NAL9602](ERROR): Failed to receive proper response when querying signal strength for MT queue check. 2021-08-03T13:56:12.416Z,1627998972.416 [NAL9602](ERROR): received: +CSQ:0 OK 2021-08-03T13:59:57.645Z,1627999197.645 [DataOverHttps](IMPORTANT): SBD MTMSN=20210803T135852 2021-08-03T14:00:05.027Z,1627999205.027 [DataOverHttps](INFO): Received command:restart logs