2019-05-19T21:02:45.660Z,1558299765.660 [DataOverHttps](INFO): Received command:restart logs
2019-05-19T21:02:45.739Z,1558299765.739 [CommandLine](IMPORTANT): got command restart logs
2019-05-19T21:02:50.119Z,1558299770.119 [CommandLine](IMPORTANT): got command maintain
2019-05-19T21:03:02.697Z,1558299782.697 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-19T21:03:02.697Z,1558299782.697 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 2
2019-05-19T21:03:02.697Z,1558299782.697 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-19T21:03:02.708Z,1558299782.708 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-19T21:03:03.112Z,1558299783.112 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-19T21:03:03.112Z,1558299783.112 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 2
2019-05-19T21:03:32.731Z,1558299812.731 [CommandLine](IMPORTANT): got command maintain sensor Depth_Keller.depth 0.000000 meter
2019-05-19T21:03:32.732Z,1558299812.732 [ComponentRegistry](DEBUG): SyncComponent "Maintain_Depth_Keller.depth" handled in the control thread.
2019-05-19T21:03:33.012Z,1558299813.012 [controlThread](DEBUG): Component order: CycleStarter,Depth_Keller,NAL9602,Onboard,DAT,ESPComponent,PAR_Licor,Depth_Keller,PAR_Licor,Maintain_Depth_Keller.depth,DepthRateCalculator,PitchRateCalculator,SpeedCalculator,TempGradientCalculator,YawRateCalculator,ElevatorOffsetCalculator,DeadReckonUsingMultipleVelocitySources,NavChart,UniversalFixResidualReporter,MissionManager,VerticalControl,HorizontalControl,SpeedControl,LoopControl,BuoyancyServo,ElevatorServo,MassServo,RudderServo,ThrusterServo,SBIT,IBIT,CBIT,Reporter,LogSplitter,
2019-05-19T21:03:38.910Z,1558299818.910 [CommandLine](IMPORTANT): got command get depth
2019-05-19T21:03:38.911Z,1558299818.911 [CommandLine](IMPORTANT): depth 0.000000 m
2019-05-19T21:04:16.390Z,1558299856.390 [DataOverHttps](IMPORTANT): SBD MTMSN=20190519T210341
2019-05-19T21:04:21.236Z,1558299861.236 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-19T21:04:21.250Z,1558299861.250 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-19T21:04:21.250Z,1558299861.250 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-19T21:04:21.301Z,1558299861.301 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-19T21:04:21.303Z,1558299861.303 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-19T21:04:21.305Z,1558299861.305 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-19T21:04:21.307Z,1558299861.307 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-19T21:04:21.308Z,1558299861.308 [sample:A.AbortSample](DEBUG): Construct.
2019-05-19T21:04:21.310Z,1558299861.310 [sample:B.Pitch](DEBUG): Construct.
2019-05-19T21:04:21.314Z,1558299861.314 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-19T21:04:21.316Z,1558299861.316 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-19T21:04:21.385Z,1558299861.385 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-19T21:04:21.394Z,1558299861.394 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-19T21:04:21.396Z,1558299861.396 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-19T21:04:21.406Z,1558299861.406 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-19T21:04:21.408Z,1558299861.408 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-19T21:04:21.419Z,1558299861.419 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-19T21:04:21.425Z,1558299861.425 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-19T21:04:21.428Z,1558299861.428 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-19T21:04:21.464Z,1558299861.464 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-19T21:04:21.495Z,1558299861.495 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-19T21:04:21.504Z,1558299861.504 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:04:21.506Z,1558299861.506 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-19T21:04:21.536Z,1558299861.536 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-19T21:04:21.560Z,1558299861.560 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:04:21.566Z,1558299861.566 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:04:21.613Z,1558299861.613 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-19T21:04:21.613Z,1558299861.613 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-19T21:04:26.158Z,1558299866.158 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-19T21:04:26.159Z,1558299866.159 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-19T21:04:26.160Z,1558299866.160 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-19T21:04:26.160Z,1558299866.160 [CommandLine](IMPORTANT): got command run 
2019-05-19T21:04:26.162Z,1558299866.162 [CommandLine](IMPORTANT): Running 
2019-05-19T21:04:26.340Z,1558299866.340 [Default] Stopped
2019-05-19T21:04:26.340Z,1558299866.340 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-19T21:04:26.340Z,1558299866.340 [Default:B.GoToSurface] Stopped
2019-05-19T21:04:26.341Z,1558299866.341 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-19T21:04:26.341Z,1558299866.341 [Default:CheckIn] Stopped
2019-05-19T21:04:26.341Z,1558299866.341 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-19T21:04:26.341Z,1558299866.341 [Default:CheckIn:C.Wait] Stopped
2019-05-19T21:04:26.341Z,1558299866.341 [Default:CheckIn:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-19T21:04:26.341Z,1558299866.341 [MissionManager](IMPORTANT): Started mission sample
2019-05-19T21:04:26.341Z,1558299866.341 [sample] Running Loop=1
2019-05-19T21:04:26.341Z,1558299866.341 [sample](DEBUG): Aggregate::initialize sample
2019-05-19T21:04:26.342Z,1558299866.342 [sample:A.AbortSample] Running Loop=1
2019-05-19T21:04:26.342Z,1558299866.342 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-19T21:04:26.342Z,1558299866.342 [sample:B.Pitch] Running Loop=1
2019-05-19T21:04:26.342Z,1558299866.342 [sample:B.Pitch](DEBUG): Initialize.
2019-05-19T21:04:26.342Z,1558299866.342 [sample:C.SetSpeed] Running Loop=1
2019-05-19T21:04:26.342Z,1558299866.342 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-19T21:04:26.342Z,1558299866.342 [sample:E] Running Loop=1
2019-05-19T21:04:26.343Z,1558299866.343 [sample:E] Stopped
2019-05-19T21:04:26.343Z,1558299866.343 [sample:F] Running Loop=1
2019-05-19T21:04:26.343Z,1558299866.343 [sample:C.SetSpeed] Running Loop=1
2019-05-19T21:04:26.343Z,1558299866.343 [sample:B.Pitch] Running Loop=1
2019-05-19T21:04:26.343Z,1558299866.343 [sample:A.AbortSample] Running Loop=1
2019-05-19T21:04:26.723Z,1558299866.723 [sample:F] Stopped
2019-05-19T21:04:26.723Z,1558299866.723 [sample:SampleRepeater] Running Loop=1
2019-05-19T21:04:26.724Z,1558299866.724 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-19T21:04:26.724Z,1558299866.724 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-19T21:04:26.724Z,1558299866.724 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-19T21:04:27.128Z,1558299867.128 [sample:SampleAtDepth] Running Loop=1
2019-05-19T21:04:27.128Z,1558299867.128 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-19T21:04:27.128Z,1558299867.128 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-19T21:04:27.128Z,1558299867.128 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-19T21:04:27.128Z,1558299867.128 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-19T21:04:27.129Z,1558299867.129 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-19T21:04:27.129Z,1558299867.129 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-19T21:04:27.129Z,1558299867.129 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-19T21:04:27.129Z,1558299867.129 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-19T21:04:27.536Z,1558299867.536 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-19T21:04:27.536Z,1558299867.536 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-19T21:04:27.536Z,1558299867.536 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-19T21:04:27.536Z,1558299867.536 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-19T21:04:27.536Z,1558299867.536 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-19T21:04:27.537Z,1558299867.537 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-19T21:04:27.537Z,1558299867.537 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-19T21:04:27.537Z,1558299867.537 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-19T21:04:27.537Z,1558299867.537 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-19T21:04:27.948Z,1558299867.948 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-19T21:04:27.948Z,1558299867.948 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-19T21:04:27.949Z,1558299867.949 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-19T21:04:27.949Z,1558299867.949 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-19T21:04:27.949Z,1558299867.949 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-19T21:04:31.577Z,1558299871.577 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-19T21:04:31.578Z,1558299871.578 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-19T21:04:31.985Z,1558299871.985 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-19T21:04:31.986Z,1558299871.986 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-19T21:04:32.383Z,1558299872.383 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-19T21:04:33.662Z,1558299873.662 [ESPComponent](INFO): powering up ESP
2019-05-19T21:04:33.662Z,1558299873.662 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-19T21:04:33.681Z,1558299873.681 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-05-19T21:04:33.830Z,1558299873.830 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-19T21:04:34.065Z,1558299874.065 [ESPComponent](INFO): console:
2019-05-19T21:04:34.799Z,1558299874.799 [ESPComponent](INFO): console:

2019-05-19T21:04:35.211Z,1558299875.211 [ESPComponent](INFO): console:NAND:  256 MiB
2019-05-19T21:04:35.605Z,1558299875.605 [ESPComponent](INFO): console:
BOOTMODE: SPI
2019-05-19T21:04:36.085Z,1558299876.085 [ESPComponent](INFO): console:
reading SPI NOR..
2019-05-19T21:04:37.220Z,1558299877.220 [ESPComponent](INFO): console:Done
2019-05-19T21:04:37.629Z,1558299877.629 [ESPComponent](INFO): console:

2019-05-19T21:04:38.034Z,1558299878.034 [ESPComponent](INFO): console:

2019-05-19T21:04:38.433Z,1558299878.433 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 13:08:14)
2019-05-19T21:04:38.837Z,1558299878.837 [ESPComponent](INFO): console:

2019-05-19T21:04:39.245Z,1558299879.245 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-05-19T21:04:39.650Z,1558299879.650 [ESPComponent](INFO): console:
flash params are already written into flash
2019-05-19T21:04:40.057Z,1558299880.057 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-05-19T21:04:40.453Z,1558299880.453 [ESPComponent](INFO): console:
In:    serial
2019-05-19T21:04:40.861Z,1558299880.861 [ESPComponent](INFO): console:
Out:   serial
2019-05-19T21:04:41.266Z,1558299881.266 [ESPComponent](INFO): console:
Err:   serial
2019-05-19T21:04:41.665Z,1558299881.665 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-05-19T21:04:42.069Z,1558299882.069 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-05-19T21:04:42.478Z,1558299882.478 [ESPComponent](INFO): console:
mmc1 is available
2019-05-19T21:04:42.880Z,1558299882.880 [ESPComponent](INFO): console:
reaage
2019-05-19T21:04:43.281Z,1558299883.281 [ESPComponent](INFO): console:

2019-05-19T21:04:43.685Z,1558299883.685 [ESPComponent](INFO): console:
1681452 bytes read
2019-05-19T21:04:44.094Z,1558299884.094 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-05-19T21:04:44.498Z,1558299884.498 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-05-19T21:04:44.906Z,1558299884.906 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-05-19T21:04:45.305Z,1558299885.305 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-05-19T21:04:45.706Z,1558299885.706 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-05-19T21:04:46.109Z,1558299886.109 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-05-19T21:04:46.514Z,1558299886.514 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-05-19T21:04:46.917Z,1558299886.917 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-05-19T21:04:47.321Z,1558299887.321 [ESPComponent](INFO): console:
OK
2019-05-19T21:04:47.726Z,1558299887.726 [ESPComponent](INFO): console:

2019-05-19T21:04:48.133Z,1558299888.133 [ESPComponent](INFO): console:
Starting kernel ...
2019-05-19T21:04:48.532Z,1558299888.532 [ESPComponent](INFO): console:

2019-05-19T21:04:48.938Z,1558299888.938 [ESPComponent](INFO): console:
Uncompressing Linux... done, booting the kernel.
2019-05-19T21:04:49.341Z,1558299889.341 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-05-19T21:04:49.746Z,1558299889.746 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT data cache, VIVT instruction cache
2019-05-19T21:04:50.149Z,1558299890.149 [ESPComponent](INFO): console:
[    0.00] Machine: NXP EA313X
2019-05-19T21:04:50.554Z,1558299890.554 [ESPComponent](INFO): console:
[    0.00] Memory policy: ECC disabled, Data cache writeback
2019-05-19T21:04:50.966Z,1558299890.966 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-05-19T21:04:51.366Z,1558299891.366 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-05-19T21:04:51.764Z,1558299891.764 [ESPComponent](INFO): console:
[    0.29] MBARI ESP 3G
2019-05-19T21:04:52.174Z,1558299892.174 [ESPComponent](INFO): console:
[    0.39] bio: create slab <bio-0> at 0
2019-05-19T21:04:52.577Z,1558299892.577 [ESPComponent](INFO): console:
[    0.46] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:52.983Z,1558299892.983 [ESPComponent](INFO): console:
[    0.48] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:53.382Z,1558299893.382 [ESPComponent](INFO): console:
[    0.50] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:53.787Z,1558299893.787 [ESPComponent](INFO): console:
[    0.52] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:54.198Z,1558299894.198 [ESPComponent](INFO): console:
[    0.54] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:54.605Z,1558299894.605 [ESPComponent](INFO): console:
[    0.56] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:04:54.998Z,1558299894.998 [ESPComponent](INFO): console:
[    0.56] NetWinder Floating Point Emulator V0.97 (double precision)
2019-05-19T21:04:55.405Z,1558299895.405 [ESPComponent](INFO): console:
[    0.58] yaffs Dec 14 2018 09:19:05 Installing. 
2019-05-19T21:04:55.806Z,1558299895.806 [ESPComponent](INFO): console:
[    0.72] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-05-19T21:04:56.210Z,1558299896.210 [ESPComponent](INFO): console:
[    2.18] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-05-19T21:04:56.612Z,1558299896.612 [ESPComponent](INFO): console:

2019-05-19T21:04:57.021Z,1558299897.021 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-05-19T21:04:57.421Z,1558299897.421 [ESPComponent](INFO): console:

2019-05-19T21:04:57.831Z,1558299897.831 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-19T21:04:58.227Z,1558299898.227 [ESPComponent](INFO): console:
ESPmv1
2019-05-19T21:04:58.633Z,1558299898.633 [ESPComponent](INFO): console:

2019-05-19T21:04:59.036Z,1558299899.036 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-05-19T21:04:59.445Z,1558299899.445 [ESPComponent](INFO): console:

2019-05-19T21:04:59.845Z,1558299899.845 [ESPComponent](INFO): console:Loading kernel modules
2019-05-19T21:05:00.254Z,1558299900.254 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-05-19T21:05:00.658Z,1558299900.658 [ESPComponent](INFO): console:
mount: /dev/mmcblk0p2 already mounted or /card busy
2019-05-19T21:05:01.059Z,1558299901.059 [ESPComponent](INFO): console:
Starting hotplug events dispatcher udevd
2019-05-19T21:05:01.468Z,1558299901.468 [ESPComponent](INFO): console:
Set system clock to:  Sun May 19 14:04:20 PDT 2019
2019-05-19T21:05:01.870Z,1558299901.870 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-05-19T21:05:02.273Z,1558299902.273 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-05-19T21:05:02.673Z,1558299902.673 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-05-19T21:05:03.077Z,1558299903.077 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-05-19T21:05:03.482Z,1558299903.482 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-05-19T21:05:03.884Z,1558299903.884 [ESPComponent](INFO): console:
Starting portmap...
2019-05-19T21:05:03.897Z,1558299903.897 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-19T21:05:03.897Z,1558299903.897 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 3
2019-05-19T21:05:03.897Z,1558299903.897 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-19T21:05:03.937Z,1558299903.937 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-19T21:05:04.294Z,1558299904.294 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-05-19T21:05:04.341Z,1558299904.341 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-19T21:05:04.341Z,1558299904.341 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 3
2019-05-19T21:05:04.698Z,1558299904.698 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2019-05-19T21:05:05.106Z,1558299905.106 [ESPComponent](INFO): console:
Network unavailable:  Local time is Sun May 19 14:04:22 PDT 2019
2019-05-19T21:05:05.506Z,1558299905.506 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-05-19T21:05:05.909Z,1558299905.909 [ESPComponent](INFO): console:
Starting thttpd...
2019-05-19T21:05:06.318Z,1558299906.318 [ESPComponent](INFO): console:
Sending discover...
2019-05-19T21:05:06.713Z,1558299906.713 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-19T21:05:07.530Z,1558299907.530 [ESPComponent](IMPORTANT): [sample #5] Explicit cartridge argument not given
2019-05-19T21:05:07.530Z,1558299907.530 [ESPComponent](IMPORTANT): [sample #5] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-19T21:05:07.531Z,1558299907.531 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=5
2019-05-19T21:05:07.543Z,1558299907.543 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-19T21:05:07.544Z,1558299907.544 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-19T21:05:07.944Z,1558299907.944 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-19T21:05:07.945Z,1558299907.945 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-19T21:05:07.945Z,1558299907.945 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-19T21:05:07.945Z,1558299907.945 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-19T21:05:07.945Z,1558299907.945 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-19T21:05:08.338Z,1558299908.338 [ESPComponent](IMPORTANT): [sample #5] ESP sampling state: S_PREPARING_SHOW_LOG (@5)
2019-05-19T21:05:08.352Z,1558299908.352 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-19T21:05:08.737Z,1558299908.737 [ESPComponent](IMPORTANT): [sample #5] ESP sampling state: S_PREPARING_SHOW_STATUS (@5)
2019-05-19T21:05:10.756Z,1558299910.756 [ESPComponent](IMPORTANT): [sample #5] ESP sampling state: S_LOADING_CARTRIDGE (@5)
2019-05-19T21:05:23.342Z,1558299923.342 [CommandLine](IMPORTANT): got command stop
2019-05-19T21:05:23.343Z,1558299923.343 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-19T21:05:23.701Z,1558299923.701 [MissionManager](INFO): MissionManager is completed.
2019-05-19T21:05:23.701Z,1558299923.701 [MissionManager](INFO): Uninitializing Mission sample
2019-05-19T21:05:23.701Z,1558299923.701 [sample] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-19T21:05:23.702Z,1558299923.702 [sample:A.AbortSample] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-19T21:05:23.702Z,1558299923.702 [sample:B.Pitch] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:C.SetSpeed] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-19T21:05:23.702Z,1558299923.702 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleRepeater] Stopped
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleRepeater:Sample] Stopped
2019-05-19T21:05:23.703Z,1558299923.703 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-19T21:05:24.090Z,1558299924.090 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-19T21:05:24.091Z,1558299924.091 [ESPComponent](IMPORTANT): [sample #5] Stop sampling requested.
2019-05-19T21:05:24.099Z,1558299924.099 [MissionManager](IMPORTANT): Started mission Default
2019-05-19T21:05:24.099Z,1558299924.099 [Default] Running Loop=1
2019-05-19T21:05:24.099Z,1558299924.099 [Default](DEBUG): Aggregate::initialize Default
2019-05-19T21:05:24.099Z,1558299924.099 [Default:B.GoToSurface] Running Loop=1
2019-05-19T21:05:24.099Z,1558299924.099 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-19T21:05:24.099Z,1558299924.099 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-19T21:05:24.100Z,1558299924.100 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-19T21:05:24.100Z,1558299924.100 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-19T21:05:24.100Z,1558299924.100 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-19T21:05:24.101Z,1558299924.101 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-19T21:05:24.101Z,1558299924.101 [Default:A.Wait] Running Loop=1
2019-05-19T21:05:24.101Z,1558299924.101 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-19T21:05:24.492Z,1558299924.492 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.stop
2019-05-19T21:05:24.898Z,1558299924.898 [ESPComponent](IMPORTANT): [sample #5] ESP sampling state: S_STOPPING
2019-05-19T21:05:37.448Z,1558299937.448 [Default:A.Wait](INFO): Done Waiting.
2019-05-19T21:05:37.448Z,1558299937.448 [Default:A.Wait] Stopped
2019-05-19T21:05:37.448Z,1558299937.448 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-19T21:05:37.848Z,1558299937.848 [Default:CheckIn] Running Loop=1
2019-05-19T21:05:37.848Z,1558299937.848 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-19T21:05:37.848Z,1558299937.848 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-19T21:05:39.433Z,1558299939.433 [NAL9602](DEBUG): Fix Requested
2019-05-19T21:05:42.279Z,1558299942.279 [ESPComponent](IMPORTANT): [sample #5] ESP sampling sequence completed normally.
2019-05-19T21:05:42.279Z,1558299942.279 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=5
2019-05-19T21:05:42.681Z,1558299942.681 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-19T21:05:42.682Z,1558299942.682 [ESPComponent](IMPORTANT): [sample #5] ESP log summary report (1 messages):
@14:05:17.60 Selecting Cartridge 5

2019-05-19T21:05:42.682Z,1558299942.682 [ESPComponent](INFO): powering down ESP
2019-05-19T21:05:42.683Z,1558299942.683 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-19T21:06:53.806Z,1558300013.806 [DataOverHttps](IMPORTANT): SBD MTMSN=20190519T210619
2019-05-19T21:06:58.564Z,1558300018.564 [DataOverHttps](INFO): Received command:load Maintenance/sample.xml;set sample.Depth 0 meter;set sample.WaitBeforeSample 3 second;set sample:SampleAtDepth.TargetDepth 0 meter;run 
2019-05-19T21:06:58.577Z,1558300018.577 [CommandLine](IMPORTANT): got command load ./Missions/Maintenance/sample.xml
2019-05-19T21:06:58.578Z,1558300018.578 [MissionManager](INFO): Loading Mission: ./Missions/Maintenance/sample.xml
2019-05-19T21:06:58.616Z,1558300018.616 [MissionManager](INFO): DefineArg sample.MissionTimeout = 90.000000 min
2019-05-19T21:06:58.627Z,1558300018.627 [MissionManager](INFO): DefineArg sample.Depth = 7.000000 m
2019-05-19T21:06:58.633Z,1558300018.633 [MissionManager](INFO): DefineArg sample.NumberOfSamples = 1.000000 count
2019-05-19T21:06:58.635Z,1558300018.635 [MissionManager](INFO): DefineArg sample.WaitBeforeSample = 3.000000 min
2019-05-19T21:06:58.636Z,1558300018.636 [sample:A.AbortSample](DEBUG): Construct.
2019-05-19T21:06:58.641Z,1558300018.641 [sample:B.Pitch](DEBUG): Construct.
2019-05-19T21:06:58.650Z,1558300018.650 [sample:C.SetSpeed](DEBUG): Construct.
2019-05-19T21:06:58.651Z,1558300018.651 [MissionManager](INFO): Inserting Stack: Missions/Insert/SampleAtDepth.xml
2019-05-19T21:06:58.764Z,1558300018.764 [MissionManager](INFO): DefineArg sample:SampleAtDepth.TargetDepth = 5.000000 m
2019-05-19T21:06:58.766Z,1558300018.766 [MissionManager](INFO): DefineArg sample:SampleAtDepth.SettleTime = 10.000000 s
2019-05-19T21:06:58.768Z,1558300018.768 [MissionManager](INFO): DefineArg sample:SampleAtDepth.MaxWaitNotReachingDepth = 3.000000 h
2019-05-19T21:06:58.770Z,1558300018.770 [MissionManager](INFO): DefineArg sample:SampleAtDepth.RotateOnly = 0.000000 bool
2019-05-19T21:06:58.773Z,1558300018.773 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseCANONSampler = 0.000000 bool
2019-05-19T21:06:58.775Z,1558300018.775 [MissionManager](INFO): DefineArg sample:SampleAtDepth.UseESP = 1.000000 bool
2019-05-19T21:06:58.777Z,1558300018.777 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTriggerTimeout = 1.000000 min
2019-05-19T21:06:58.780Z,1558300018.780 [MissionManager](INFO): DefineArg sample:SampleAtDepth.CANONSamplerTimeout = 6.000000 min
2019-05-19T21:06:58.783Z,1558300018.783 [MissionManager](INFO): DefineArg sample:SampleAtDepth.BuoyancyNeutral = 90.000001 cc
2019-05-19T21:06:58.786Z,1558300018.786 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Construct.
2019-05-19T21:06:58.790Z,1558300018.790 [sample:SampleAtDepth:ApproachDepth:B.Pitch:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:06:58.793Z,1558300018.793 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Construct.
2019-05-19T21:06:58.798Z,1558300018.798 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Construct Wait.
2019-05-19T21:06:58.805Z,1558300018.805 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:06:58.811Z,1558300018.811 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:E:A_Timeout:B.Execute](DEBUG): Construct Execute.
2019-05-19T21:06:58.827Z,1558300018.827 [MissionManager](DEBUG): 
<?xml version="1.0" encoding="UTF-8"?>
<!-- ====================
     Generated by TethysL
     ==================== -->
<Mission xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xmlns="Tethys"
         xmlns:Units="Tethys/Units"
         xmlns:Guidance="Tethys/Guidance"
         xmlns:Control="Tethys/Control"
         xsi:schemaLocation="Tethys http://okeanids.mbari.org/tethys/Xml/Tethys.xsd
                             Tethys/Units http://okeanids.mbari.org/tethys/Xml/Units.xsd
                             Tethys/Guidance http://okeanids.mbari.org/tethys/Xml/Guidance.xsd
                             Tethys/Control http://okeanids.mbari.org/tethys/Xml/Control.xsd"
       Id="sample">

    <Description>
        This mission is designed to be run in the test tank only and samples
        whichever sampler is installed once the vehicle reaches the target
        depth.
    </Description>

    <DefineArg Name="MissionTimeout"><Description>
        How long to let the mission run.
    </Description><Units:minute/><Value>90</Value></DefineArg>

    <DefineArg Name="Depth"><Description>
        Depth to sample at.
    </Description><Units:meter/><Value>7</Value></DefineArg>

    <DefineArg Name="NumberOfSamples"><Description>
        Number of samples to take.
    </Description><Units:count/><Value>1</Value></DefineArg>

    <DefineArg Name="WaitBeforeSample"><Description>
        How long to wait between samples. This starts *before* the first sample
        to exercise the SettleTime setting in the insert aggregate.
    </Description><Units:minute/><Value>3</Value></DefineArg>

    <Timeout Duration="MissionTimeout"/>

     <Trigger:AbortSample>
     	  <Parallel/>
     </Trigger:AbortSample>

    <Guidance:Pitch>
        <Parallel/>
        <Setting><Guidance:Pitch.massPosition/><Control:VerticalControl.massDefault/></Setting>
    </Guidance:Pitch>

    <Guidance:SetSpeed>
        <Parallel/>
        <Setting><Guidance:SetSpeed.speed/><Units:meter_per_second/><Value>0</Value></Setting>
    </Guidance:SetSpeed>

    <Insert Filename="Insert/SampleAtDepth.xml"/>

    <Assign><Sequence/><Arg Name="SampleAtDepth:TargetDepth"/><Arg Name="Depth"/></Assign>

    <Assign><Sequence/><Arg Name="SampleAtDepth:SettleTime"/><Arg Name="WaitBeforeSample"/></Assign>

    <Aggregate Id="SampleRepeater">

        <Sequence Repeat="NumberOfSamples"/>

        <Call Id="Sample" RefId="SampleAtDepth"/>

    </Aggregate>

</Mission>


2019-05-19T21:06:58.827Z,1558300018.827 [CommandLine](IMPORTANT): Loaded ./Missions/Maintenance/sample.xml
2019-05-19T21:07:03.422Z,1558300023.422 [CommandLine](IMPORTANT): got command set sample.Depth 0.000000 meter
2019-05-19T21:07:03.423Z,1558300023.423 [CommandLine](IMPORTANT): got command set sample.WaitBeforeSample 3.000000 second
2019-05-19T21:07:03.423Z,1558300023.423 [CommandLine](IMPORTANT): got command set sample:SampleAtDepth.TargetDepth 0.000000 meter
2019-05-19T21:07:03.424Z,1558300023.424 [CommandLine](IMPORTANT): got command run 
2019-05-19T21:07:03.425Z,1558300023.425 [CommandLine](IMPORTANT): Running 
2019-05-19T21:07:03.499Z,1558300023.499 [Default] Stopped
2019-05-19T21:07:03.499Z,1558300023.499 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-19T21:07:03.499Z,1558300023.499 [Default:B.GoToSurface] Stopped
2019-05-19T21:07:03.499Z,1558300023.499 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-19T21:07:03.499Z,1558300023.499 [Default:CheckIn] Stopped
2019-05-19T21:07:03.499Z,1558300023.499 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-19T21:07:03.499Z,1558300023.499 [Default:CheckIn:Read_GPS] Stopped
2019-05-19T21:07:03.499Z,1558300023.499 [MissionManager](IMPORTANT): Started mission sample
2019-05-19T21:07:03.500Z,1558300023.500 [sample] Running Loop=1
2019-05-19T21:07:03.500Z,1558300023.500 [sample](DEBUG): Aggregate::initialize sample
2019-05-19T21:07:03.500Z,1558300023.500 [sample:A.AbortSample] Running Loop=1
2019-05-19T21:07:03.500Z,1558300023.500 [sample:A.AbortSample](INFO): Initializing AbortSample.
2019-05-19T21:07:03.500Z,1558300023.500 [sample:B.Pitch] Running Loop=1
2019-05-19T21:07:03.500Z,1558300023.500 [sample:B.Pitch](DEBUG): Initialize.
2019-05-19T21:07:03.500Z,1558300023.500 [sample:C.SetSpeed] Running Loop=1
2019-05-19T21:07:03.500Z,1558300023.500 [sample:C.SetSpeed](DEBUG): Initialize.
2019-05-19T21:07:03.505Z,1558300023.505 [sample:E] Running Loop=1
2019-05-19T21:07:03.505Z,1558300023.505 [sample:E] Stopped
2019-05-19T21:07:03.505Z,1558300023.505 [sample:F] Running Loop=1
2019-05-19T21:07:03.505Z,1558300023.505 [sample:C.SetSpeed] Running Loop=1
2019-05-19T21:07:03.506Z,1558300023.506 [sample:B.Pitch] Running Loop=1
2019-05-19T21:07:03.506Z,1558300023.506 [sample:A.AbortSample] Running Loop=1
2019-05-19T21:07:03.900Z,1558300023.900 [sample:F] Stopped
2019-05-19T21:07:03.900Z,1558300023.900 [sample:SampleRepeater] Running Loop=1
2019-05-19T21:07:03.900Z,1558300023.900 [sample:SampleRepeater](DEBUG): Aggregate::initialize sample:SampleRepeater
2019-05-19T21:07:03.900Z,1558300023.900 [sample:SampleRepeater:Sample] Running Loop=1
2019-05-19T21:07:03.900Z,1558300023.900 [sample:SampleRepeater:Sample](DEBUG): Aggregate::initialize sample:SampleRepeater:Sample
2019-05-19T21:07:04.284Z,1558300024.284 [sample:SampleAtDepth] Running Loop=1
2019-05-19T21:07:04.284Z,1558300024.284 [sample:SampleAtDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth
2019-05-19T21:07:04.284Z,1558300024.284 [sample:SampleAtDepth:ApproachDepth] Running Loop=1
2019-05-19T21:07:04.284Z,1558300024.284 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::initialize sample:SampleAtDepth:ApproachDepth
2019-05-19T21:07:04.284Z,1558300024.284 [sample:SampleAtDepth:ApproachDepth:A] Running Loop=1
2019-05-19T21:07:04.285Z,1558300024.285 [sample:SampleAtDepth:ApproachDepth:A](INFO): Moving to 0.000000 m 
2019-05-19T21:07:04.285Z,1558300024.285 [sample:SampleAtDepth:ApproachDepth:A] Stopped
2019-05-19T21:07:04.285Z,1558300024.285 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Running Loop=1
2019-05-19T21:07:04.286Z,1558300024.286 [sample:SampleAtDepth:ApproachDepth:B.Pitch](DEBUG): Initialize.
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:ApproachDepth:B.Pitch] Stopped
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:ApproachDepth](INFO): Completed sample:SampleAtDepth:ApproachDepth
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:ApproachDepth] Stopped
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:ApproachDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:ApproachDepth
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:SampleWrapper] Running Loop=1
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper
2019-05-19T21:07:04.693Z,1558300024.693 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-19T21:07:04.694Z,1558300024.694 [sample:SampleAtDepth:SampleWrapper:A.Pitch](DEBUG): Initialize.
2019-05-19T21:07:04.694Z,1558300024.694 [sample:SampleAtDepth:SampleWrapper:B] Running Loop=1
2019-05-19T21:07:05.106Z,1558300025.106 [DeadReckonUsingMultipleVelocitySources](FAULT): Unable to read the rotation from vehicle frame to navigation frame for more than 120 seconds.
2019-05-19T21:07:05.106Z,1558300025.106 [DeadReckonUsingMultipleVelocitySources] Software Fault, FailCount= 4
2019-05-19T21:07:05.106Z,1558300025.106 [DeadReckonUsingMultipleVelocitySources](ERROR): Software Fault
2019-05-19T21:07:05.109Z,1558300025.109 [sample:SampleAtDepth:SampleWrapper:B](IMPORTANT): At 0.000000 m , settling for 0.050000 min 
2019-05-19T21:07:05.109Z,1558300025.109 [sample:SampleAtDepth:SampleWrapper:B] Stopped
2019-05-19T21:07:05.110Z,1558300025.110 [sample:SampleAtDepth:SampleWrapper:C.Wait] Running Loop=1
2019-05-19T21:07:05.110Z,1558300025.110 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Initialize Wait Component.
2019-05-19T21:07:05.110Z,1558300025.110 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Running Loop=1
2019-05-19T21:07:05.120Z,1558300025.120 [CBIT](ERROR): Software Fault in component: DeadReckonUsingMultipleVelocitySources
2019-05-19T21:07:05.573Z,1558300025.573 [CBIT](INFO): Clearing failed state for component DeadReckonUsingMultipleVelocitySources
2019-05-19T21:07:05.573Z,1558300025.573 [DeadReckonUsingMultipleVelocitySources] No Fault, FailCount= 4
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:C.Wait](INFO): Done Waiting.
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:C.Wait] Stopped
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:C.Wait](DEBUG): Uninitialize Wait Component.
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Running Loop=1
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Running Loop=1
2019-05-19T21:07:08.733Z,1558300028.733 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Running Loop=1
2019-05-19T21:07:08.734Z,1558300028.734 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Running Loop=1
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler] Stopped
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleCANONSampler
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:A] Stopped
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:B] Stopped
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleCANONSampler:TriggerCANONSampler] Stopped
2019-05-19T21:07:09.143Z,1558300029.143 [sample:SampleAtDepth:SampleWrapper:SampleESP] Running Loop=1
2019-05-19T21:07:09.144Z,1558300029.144 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::initialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-19T21:07:09.144Z,1558300029.144 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Running Loop=1
2019-05-19T21:07:09.544Z,1558300029.544 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sampling
2019-05-19T21:07:10.814Z,1558300030.814 [ESPComponent](INFO): powering up ESP
2019-05-19T21:07:10.814Z,1558300030.814 [ESPComponent](INFO): powering up ESP secondary power supply
2019-05-19T21:07:10.836Z,1558300030.836 [ESPComponent](IMPORTANT): Starting PPPD with command:/sbin/pppd xonxoff asyncmap A0000 /dev/ttyTX1 linkname esp noauth local lock 115200 10.89.8.2:10.89.8.3 persist maxfail 0 holdoff 10 lcp-echo-interval 60 lcp-echo-failure 3 proxyarp ktune deflate 12 ms-dns 8.8.8.8
2019-05-19T21:07:10.950Z,1558300030.950 [ESPComponent](IMPORTANT): Waiting for ESP to connect (timeout=150.0000)
2019-05-19T21:07:11.225Z,1558300031.225 [ESPComponent](INFO): console:
2019-05-19T21:07:11.964Z,1558300031.964 [ESPComponent](INFO): console:

2019-05-19T21:07:12.368Z,1558300032.368 [ESPComponent](INFO): console:NAND:  256 MiB
2019-05-19T21:07:12.762Z,1558300032.762 [ESPComponent](INFO): console:
BOOTMODE: SPI
2019-05-19T21:07:13.237Z,1558300033.237 [ESPComponent](INFO): console:
reading SPI NOR..
2019-05-19T21:07:14.381Z,1558300034.381 [ESPComponent](INFO): console:Done
2019-05-19T21:07:14.785Z,1558300034.785 [ESPComponent](INFO): console:

2019-05-19T21:07:15.190Z,1558300035.190 [ESPComponent](INFO): console:

2019-05-19T21:07:15.593Z,1558300035.593 [ESPComponent](INFO): console:
U-Boot 2009.11-mbariC (Apr 02 2019 - 13:08:14)
2019-05-19T21:07:15.997Z,1558300035.997 [ESPComponent](INFO): console:

2019-05-19T21:07:16.408Z,1558300036.408 [ESPComponent](INFO): console:
MBARI LPC31xx ESP 3G
2019-05-19T21:07:16.813Z,1558300036.813 [ESPComponent](INFO): console:
flash params are already written into flash
2019-05-19T21:07:17.220Z,1558300037.220 [ESPComponent](INFO): console:
DRAM:  64 MB
2019-05-19T21:07:17.628Z,1558300037.628 [ESPComponent](INFO): console:
In:    serial
2019-05-19T21:07:18.013Z,1558300038.013 [ESPComponent](INFO): console:
Out:   serial
2019-05-19T21:07:18.421Z,1558300038.421 [ESPComponent](INFO): console:
Err:   serial
2019-05-19T21:07:18.822Z,1558300038.822 [ESPComponent](INFO): console:
Net:   ks8851_mll
2019-05-19T21:07:19.225Z,1558300039.225 [ESPComponent](INFO): console:
Hit <ctrl-C> to stop autoboot:  1  0 
2019-05-19T21:07:19.637Z,1558300039.637 [ESPComponent](INFO): console:
mmc1 is available
2019-05-19T21:07:20.038Z,1558300040.038 [ESPComponent](INFO): console:
reading uImage
2019-05-19T21:07:20.438Z,1558300040.438 [ESPComponent](INFO): console:

2019-05-19T21:07:20.851Z,1558300040.851 [ESPComponent](INFO): console:
1681452 bytes read
2019-05-19T21:07:21.251Z,1558300041.251 [ESPComponent](INFO): console:
## Booting kernel from Legacy Image at 31000000 ...
2019-05-19T21:07:21.661Z,1558300041.661 [ESPComponent](INFO): console:
   Image Name:   Linux-2.6.33-ea3131-mbari6
2019-05-19T21:07:22.069Z,1558300042.069 [ESPComponent](INFO): console:
   Image Type:   ARM Linux Kernel Image (uncompressed)
2019-05-19T21:07:22.474Z,1558300042.474 [ESPComponent](INFO): console:
   Data Size:    1681388 Bytes =  1.6 MB
2019-05-19T21:07:22.873Z,1558300042.873 [ESPComponent](INFO): console:
   Load Address: 30008000
2019-05-19T21:07:23.270Z,1558300043.270 [ESPComponent](INFO): console:
   Entry Point:  30008000
2019-05-19T21:07:23.674Z,1558300043.674 [ESPComponent](INFO): console:
   Verifying Checksum ... OK
2019-05-19T21:07:24.077Z,1558300044.077 [ESPComponent](INFO): console:
   Loading Kernel Image ... OK
2019-05-19T21:07:24.481Z,1558300044.481 [ESPComponent](INFO): console:
OK
2019-05-19T21:07:24.882Z,1558300044.882 [ESPComponent](INFO): console:

2019-05-19T21:07:25.305Z,1558300045.305 [ESPComponent](INFO): console:
Starting kernel ...
2019-05-19T21:07:25.690Z,1558300045.690 [ESPComponent](INFO): console:

2019-05-19T21:07:26.094Z,1558300046.094 [ESPComponent](INFO): console:
Uncompressing Linux... done, booting the kernel.
2019-05-19T21:07:26.499Z,1558300046.499 [ESPComponent](INFO): console:
[    0.00] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=00053177
2019-05-19T21:07:26.921Z,1558300046.921 [ESPComponent](INFO): console:
[    0.00] CPU: VIVT data cache, VIVT instruction cache
2019-05-19T21:07:27.317Z,1558300047.317 [ESPComponent](INFO): console:
[    0.00] Machine: NXP EA313X
2019-05-19T21:07:27.721Z,1558300047.721 [ESPComponent](INFO): console:
[    0.00] Memory policy: ECC disabled, Data cache writeback
2019-05-19T21:07:28.131Z,1558300048.131 [ESPComponent](INFO): console:
[    0.00] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 16256
2019-05-19T21:07:28.518Z,1558300048.518 [ESPComponent](INFO): console:
[    0.24] Mount-cache hash table entries: 512
2019-05-19T21:07:28.921Z,1558300048.921 [ESPComponent](INFO): console:
[    0.30] MBARI ESP 3G
2019-05-19T21:07:29.325Z,1558300049.325 [ESPComponent](INFO): console:
[    0.40] bio: create slab <bio-0> at 0
2019-05-19T21:07:29.731Z,1558300049.731 [ESPComponent](INFO): console:
[    0.47] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:30.134Z,1558300050.134 [ESPComponent](INFO): console:
[    0.49] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:30.543Z,1558300050.543 [ESPComponent](INFO): console:
[    0.51] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:30.949Z,1558300050.949 [ESPComponent](INFO): console:
[    0.53] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:31.346Z,1558300051.346 [ESPComponent](INFO): console:
[    0.55] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:31.751Z,1558300051.751 [ESPComponent](INFO): console:
[    0.57] i2c i2c-0: Master timed out. stat = 2a00, cntrl = 000e. Resetting master...
2019-05-19T21:07:32.165Z,1558300052.165 [ESPComponent](INFO): console:
[    0.57] NetWinder Floating Point Emulator V0.97 (double precision)
2019-05-19T21:07:32.581Z,1558300052.581 [ESPComponent](INFO): console:
[    0.59] yaffs Dec 14 2018 09:19:05 Installing. 
2019-05-19T21:07:32.972Z,1558300052.972 [ESPComponent](INFO): console:
[    0.73] m25p80 spi0.3: m25p80 found s25sl032a flash
2019-05-19T21:07:33.377Z,1558300053.377 [ESPComponent](INFO): console:
[    2.27] VFS: Mounted root (ext2 filesystem) readonly on device 179:2.
2019-05-19T21:07:33.769Z,1558300053.769 [ESPComponent](INFO): console:

2019-05-19T21:07:34.179Z,1558300054.179 [ESPComponent](INFO): console:INIT: version 2.85 booting
2019-05-19T21:07:34.585Z,1558300054.585 [ESPComponent](INFO): console:

2019-05-19T21:07:34.982Z,1558300054.982 [ESPComponent](INFO): console:MBARI ESP Embedded Linux    http://www.mbari.org   mailto:brent@mbari.org
2019-05-19T21:07:35.389Z,1558300055.389 [ESPComponent](INFO): console:
ESPmv1
2019-05-19T21:07:35.789Z,1558300055.789 [ESPComponent](INFO): console:

2019-05-19T21:07:36.193Z,1558300056.193 [ESPComponent](INFO): console:INIT: Entering runlevel: 3
2019-05-19T21:07:36.601Z,1558300056.601 [ESPComponent](INFO): console:

2019-05-19T21:07:37.004Z,1558300057.004 [ESPComponent](INFO): console:Loading kernel modules
2019-05-19T21:07:37.425Z,1558300057.425 [ESPComponent](INFO): console:
Mounting filesystems and adding swapfiles listed in /etc/fstab
2019-05-19T21:07:37.829Z,1558300057.829 [ESPComponent](INFO): console:
mount: /dev/mmcblk0p2 already mounted or /card busy
2019-05-19T21:07:38.232Z,1558300058.232 [ESPComponent](INFO): console:
Starting hotplug events dispatcher udevd
2019-05-19T21:07:38.633Z,1558300058.633 [ESPComponent](INFO): console:
Set system clock to:  Sun May 19 14:06:57 PDT 2019
2019-05-19T21:07:39.021Z,1558300059.021 [ESPComponent](INFO): console:
Starting syslogd klogd...
2019-05-19T21:07:39.430Z,1558300059.430 [ESPComponent](INFO): console:
Bringing up interface lo ...
2019-05-19T21:07:39.833Z,1558300059.833 [ESPComponent](INFO): console:
lo IP=127.0.0.1
2019-05-19T21:07:40.234Z,1558300060.234 [ESPComponent](INFO): console:
Packet forwarding enabled
2019-05-19T21:07:40.637Z,1558300060.637 [ESPComponent](INFO): console:
Bringing up interface ppp2 ...
2019-05-19T21:07:41.050Z,1558300061.050 [ESPComponent](INFO): console:
Starting portmap...
2019-05-19T21:07:41.454Z,1558300061.454 [ESPComponent](INFO): console:
Bringing up interface eth0 ...
2019-05-19T21:07:41.855Z,1558300061.855 [ESPComponent](INFO): console:
Missing Network -- skipping nfs mounts
2019-05-19T21:07:42.254Z,1558300062.254 [ESPComponent](INFO): console:
Network unavailable:  Local time is Sun May 19 14:06:59 PDT 2019
2019-05-19T21:07:42.673Z,1558300062.673 [ESPComponent](INFO): console:
Determining IP configuration for eth0....udhcpc (v1.11.2) started
2019-05-19T21:07:43.077Z,1558300063.077 [ESPComponent](INFO): console:
Starting thttpd...
2019-05-19T21:07:43.477Z,1558300063.477 [ESPComponent](INFO): console:
Sending discover...
2019-05-19T21:07:43.879Z,1558300063.879 [ESPComponent](INFO): console:

2019-05-19T21:07:44.279Z,1558300064.279 [ESPComponent](IMPORTANT): ESP has connected as client
2019-05-19T21:07:45.089Z,1558300065.089 [ESPComponent](IMPORTANT): [sample #6] Explicit cartridge argument not given
2019-05-19T21:07:45.089Z,1558300065.089 [ESPComponent](IMPORTANT): [sample #6] ESP sampling sequence starting. Sampling state: S_WAITING_INITIAL_PROMPT
2019-05-19T21:07:45.090Z,1558300065.090 [ESPComponent](DEBUG): Writing samplingActive=1, sampleNumber=6
2019-05-19T21:07:45.131Z,1558300065.131 [sample:SampleAtDepth:SampleWrapper:SampleESP:TriggerESP] Stopped
2019-05-19T21:07:45.131Z,1558300065.131 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Running Loop=1
2019-05-19T21:07:45.500Z,1558300065.500 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-19T21:07:45.501Z,1558300065.501 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](ERROR): data element is not active.
2019-05-19T21:07:45.502Z,1558300065.502 [sample:SampleAtDepth:SampleWrapper:SampleESP:B](IMPORTANT): ESP sampling at 0.000000 m in nan degC water with nan ug/l chlorophyll fluorescence.
2019-05-19T21:07:45.502Z,1558300065.502 [sample:SampleAtDepth:SampleWrapper:SampleESP:B] Stopped
2019-05-19T21:07:45.502Z,1558300065.502 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Running Loop=1
2019-05-19T21:07:45.889Z,1558300065.889 [ESPComponent](IMPORTANT): [sample #6] ESP sampling state: S_PREPARING_SHOW_LOG (@5)
2019-05-19T21:07:45.904Z,1558300065.904 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP](DEBUG): Initialize ReadDataComponent to sense ESPComponent.sample_number
2019-05-19T21:07:46.293Z,1558300066.293 [ESPComponent](IMPORTANT): [sample #6] ESP sampling state: S_PREPARING_SHOW_STATUS (@5)
2019-05-19T21:07:48.328Z,1558300068.328 [ESPComponent](IMPORTANT): [sample #6] ESP sampling state: S_LOADING_CARTRIDGE (@5)
2019-05-19T21:07:48.422Z,1558300068.422 [CommandLine](IMPORTANT): got command stop
2019-05-19T21:07:48.423Z,1558300068.423 [Supervisor](INFO): Stop Mission called by CommandLine::commandStop
2019-05-19T21:07:48.752Z,1558300068.752 [MissionManager](INFO): MissionManager is completed.
2019-05-19T21:07:48.752Z,1558300068.752 [MissionManager](INFO): Uninitializing Mission sample
2019-05-19T21:07:48.752Z,1558300068.752 [sample] Stopped
2019-05-19T21:07:48.753Z,1558300068.753 [sample](DEBUG): Aggregate::uninitialize sample
2019-05-19T21:07:48.753Z,1558300068.753 [sample:A.AbortSample] Stopped
2019-05-19T21:07:48.753Z,1558300068.753 [sample:A.AbortSample](INFO): Uninitializing AbortSample.
2019-05-19T21:07:48.753Z,1558300068.753 [sample:B.Pitch] Stopped
2019-05-19T21:07:48.753Z,1558300068.753 [sample:C.SetSpeed] Stopped
2019-05-19T21:07:48.753Z,1558300068.753 [sample:C.SetSpeed](DEBUG): Uninitialize.
2019-05-19T21:07:48.753Z,1558300068.753 [sample:SampleAtDepth] Stopped
2019-05-19T21:07:48.753Z,1558300068.753 [sample:SampleAtDepth](DEBUG): Aggregate::uninitialize sample:SampleAtDepth
2019-05-19T21:07:48.753Z,1558300068.753 [sample:SampleAtDepth:SampleWrapper] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleAtDepth:SampleWrapper](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleAtDepth:SampleWrapper:A.Pitch] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleAtDepth:SampleWrapper:SampleESP] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleAtDepth:SampleWrapper:SampleESP](DEBUG): Aggregate::uninitialize sample:SampleAtDepth:SampleWrapper:SampleESP
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleAtDepth:SampleWrapper:SampleESP:WaitForESP] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleRepeater] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleRepeater](DEBUG): Aggregate::uninitialize sample:SampleRepeater
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleRepeater:Sample] Stopped
2019-05-19T21:07:48.754Z,1558300068.754 [sample:SampleRepeater:Sample](DEBUG): Aggregate::uninitialize sample:SampleRepeater:Sample
2019-05-19T21:07:49.141Z,1558300069.141 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-19T21:07:49.141Z,1558300069.141 [ESPComponent](IMPORTANT): [sample #6] Stop sampling requested.
2019-05-19T21:07:49.178Z,1558300069.178 [MissionManager](IMPORTANT): Started mission Default
2019-05-19T21:07:49.178Z,1558300069.178 [Default] Running Loop=1
2019-05-19T21:07:49.178Z,1558300069.178 [Default](DEBUG): Aggregate::initialize Default
2019-05-19T21:07:49.178Z,1558300069.178 [Default:B.GoToSurface] Running Loop=1
2019-05-19T21:07:49.178Z,1558300069.178 [Default:B.GoToSurface](DEBUG): Initialize GoToSurfaceComponent.
2019-05-19T21:07:49.179Z,1558300069.179 [Default:B.GoToSurface](DEBUG): No depth rate setting specified. Using default value of nan m/s.
2019-05-19T21:07:49.179Z,1558300069.179 [Default:B.GoToSurface](DEBUG): No pitch setting specified. Using default value of nan degrees.
2019-05-19T21:07:49.179Z,1558300069.179 [Default:B.GoToSurface](DEBUG): No speed setting specified. Using default value of 1.000000 m/s.
2019-05-19T21:07:49.180Z,1558300069.180 [Default:B.GoToSurface](DEBUG): No surface timeout specified. Using default value of 1000.000000 seconds.
2019-05-19T21:07:49.180Z,1558300069.180 [Default:B.GoToSurface](INFO): Received pitch timeout configuration 60.000000 seconds.
2019-05-19T21:07:49.180Z,1558300069.180 [Default:A.Wait] Running Loop=1
2019-05-19T21:07:49.180Z,1558300069.180 [Default:A.Wait](DEBUG): Initialize Wait Component.
2019-05-19T21:07:49.526Z,1558300069.526 [ESPComponent](IMPORTANT): Stop sampling requested. Issuing Cmd.stop
2019-05-19T21:07:49.934Z,1558300069.934 [ESPComponent](IMPORTANT): [sample #6] ESP sampling state: S_STOPPING
2019-05-19T21:08:02.469Z,1558300082.469 [Default:A.Wait](INFO): Done Waiting.
2019-05-19T21:08:02.469Z,1558300082.469 [Default:A.Wait] Stopped
2019-05-19T21:08:02.469Z,1558300082.469 [Default:A.Wait](DEBUG): Uninitialize Wait Component.
2019-05-19T21:08:02.872Z,1558300082.872 [Default:CheckIn] Running Loop=1
2019-05-19T21:08:02.872Z,1558300082.872 [Default:CheckIn](DEBUG): Aggregate::initialize Default:CheckIn
2019-05-19T21:08:02.872Z,1558300082.872 [Default:CheckIn:Read_GPS] Running Loop=1
2019-05-19T21:08:19.837Z,1558300099.837 [ESPComponent](IMPORTANT): [sample #6] ESP sampling sequence completed normally.
2019-05-19T21:08:19.837Z,1558300099.837 [ESPComponent](DEBUG): Writing samplingActive=0, sampleNumber=6
2019-05-19T21:08:20.243Z,1558300100.243 [ESPComponent](DEBUG): Resetting stopSampling to false
2019-05-19T21:08:20.244Z,1558300100.244 [ESPComponent](IMPORTANT): [sample #6] ESP log summary report (1 messages):
@14:07:54.86 Selecting Cartridge 5

2019-05-19T21:08:20.245Z,1558300100.245 [ESPComponent](INFO): powering down ESP
2019-05-19T21:08:20.245Z,1558300100.245 [ESPComponent](INFO): powering down ESP secondary power supply
2019-05-19T21:08:46.454Z,1558300126.454 [CommandLine](IMPORTANT): got command restart application
2019-05-19T21:08:47.461Z,1558300127.461 [CommandLine ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:47.461Z,1558300127.461 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:47.533Z,1558300127.533 [Supervisor](DEBUG): Uninitializing supervisor and starting cleanup.  Bye!
2019-05-19T21:08:47.533Z,1558300127.533 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:47.534Z,1558300127.534 [CommandLine](INFO): Join timeout helper Thread ID is 2538
2019-05-19T21:08:47.534Z,1558300127.534 [ComponentRegistry](INFO): Shutting down NavChartDb ThreadHandler
2019-05-19T21:08:47.534Z,1558300127.534 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:47.534Z,1558300127.534 [NavChartDb](INFO): Join timeout helper Thread ID is 2539
2019-05-19T21:08:47.917Z,1558300127.917 [NavChartDb ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:47.917Z,1558300127.917 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:47.929Z,1558300127.929 [ComponentRegistry](INFO): Shutting down WetLabsBB2FL ThreadHandler
2019-05-19T21:08:47.929Z,1558300127.929 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:47.929Z,1558300127.929 [WetLabsBB2FL](INFO): Join timeout helper Thread ID is 2540
2019-05-19T21:08:48.125Z,1558300128.125 [WetLabsBB2FL ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.125Z,1558300128.125 [WetLabsBB2FL](INFO): Powering down
2019-05-19T21:08:48.126Z,1558300128.126 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.137Z,1558300128.137 [ComponentRegistry](INFO): Shutting down CTD_NeilBrown ThreadHandler
2019-05-19T21:08:48.137Z,1558300128.137 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.137Z,1558300128.137 [CTD_NeilBrown](INFO): Join timeout helper Thread ID is 2541
2019-05-19T21:08:48.181Z,1558300128.181 [CTD_NeilBrown ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.181Z,1558300128.181 [CTD_NeilBrown](INFO): Powering down
2019-05-19T21:08:48.193Z,1558300128.193 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.209Z,1558300128.209 [ComponentRegistry](INFO): Shutting down Radio_Surface ThreadHandler
2019-05-19T21:08:48.209Z,1558300128.209 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.209Z,1558300128.209 [Radio_Surface](INFO): Join timeout helper Thread ID is 2542
2019-05-19T21:08:48.281Z,1558300128.281 [Radio_Surface](INFO): Powering down
2019-05-19T21:08:48.282Z,1558300128.282 [Radio_Surface ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.282Z,1558300128.282 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.290Z,1558300128.290 [ComponentRegistry](INFO): Shutting down DataOverHttps ThreadHandler
2019-05-19T21:08:48.290Z,1558300128.290 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.290Z,1558300128.290 [DataOverHttps](INFO): Join timeout helper Thread ID is 2543
2019-05-19T21:08:48.437Z,1558300128.437 [DataOverHttps ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.437Z,1558300128.437 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.449Z,1558300128.449 [ComponentRegistry](INFO): Shutting down logger ThreadHandler
2019-05-19T21:08:48.450Z,1558300128.450 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.450Z,1558300128.450 [logger](INFO): Join timeout helper Thread ID is 2544
2019-05-19T21:08:48.481Z,1558300128.481 [logger ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.481Z,1558300128.481 [logger ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.490Z,1558300128.490 [ComponentRegistry](INFO): Shutting down CommandLine ThreadHandler
2019-05-19T21:08:48.490Z,1558300128.490 [CommandLine ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.490Z,1558300128.490 [ComponentRegistry](INFO): Shutting down controlThread ThreadHandler
2019-05-19T21:08:48.490Z,1558300128.490 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.491Z,1558300128.491 [controlThread](INFO): Join timeout helper Thread ID is 2545
2019-05-19T21:08:48.537Z,1558300128.537 [controlThread ThreadHandler](INFO): Uninitializing protected caller thread.
2019-05-19T21:08:48.537Z,1558300128.537 [controlThread](DEBUG): Uninitializing ControlThread
2019-05-19T21:08:48.537Z,1558300128.537 [NAL9602](INFO): Powering down
2019-05-19T21:08:48.538Z,1558300128.538 [DAT](INFO): Powering down
2019-05-19T21:08:48.659Z,1558300128.659 [DepthRateCalculator](DEBUG): Uninitializing DepthRateCalculator.
2019-05-19T21:08:48.660Z,1558300128.660 [ElevatorOffsetCalculator](DEBUG): Uninitializing ElevatorOffsetCalculator.
2019-05-19T21:08:48.660Z,1558300128.660 [NavChart](DEBUG): Uninitialize NavChart Navigation.
2019-05-19T21:08:48.661Z,1558300128.661 [MissionManager](INFO): Uninitializing Mission Default
2019-05-19T21:08:48.661Z,1558300128.661 [Default] Stopped
2019-05-19T21:08:48.661Z,1558300128.661 [Default](DEBUG): Aggregate::uninitialize Default
2019-05-19T21:08:48.661Z,1558300128.661 [Default:B.GoToSurface] Stopped
2019-05-19T21:08:48.661Z,1558300128.661 [Default:B.GoToSurface](DEBUG): Uninitialize GoToSurfaceComponent.
2019-05-19T21:08:48.661Z,1558300128.661 [Default:CheckIn] Stopped
2019-05-19T21:08:48.661Z,1558300128.661 [Default:CheckIn](DEBUG): Aggregate::uninitialize Default:CheckIn
2019-05-19T21:08:48.661Z,1558300128.661 [Default:CheckIn:Read_GPS] Stopped
2019-05-19T21:08:48.664Z,1558300128.664 [VerticalControl](DEBUG): Uninitialize VerticalControlComponent.
2019-05-19T21:08:48.664Z,1558300128.664 [HorizontalControl](DEBUG): Uninitialize HorizontalControlComponent.
2019-05-19T21:08:48.664Z,1558300128.664 [SpeedControl](DEBUG): Uninitialize SpeedControlComponent.
2019-05-19T21:08:48.665Z,1558300128.665 [LoopControl](DEBUG): Uninitialize LoopControlComponent.
2019-05-19T21:08:48.665Z,1558300128.665 [BuoyancyServo](DEBUG): Uninitialize Buoyancy Servo.
2019-05-19T21:08:48.665Z,1558300128.665 [BuoyancyServo](INFO): Powering down
2019-05-19T21:08:48.677Z,1558300128.677 [ElevatorServo](DEBUG): Uninitialize Elevator Servo.
2019-05-19T21:08:48.677Z,1558300128.677 [ElevatorServo](INFO): Powering down
2019-05-19T21:08:48.678Z,1558300128.678 [MassServo](DEBUG): Uninitialize Mass Servo.
2019-05-19T21:08:48.678Z,1558300128.678 [MassServo](INFO): Powering down
2019-05-19T21:08:48.679Z,1558300128.679 [RudderServo](DEBUG): Uninitialize Rudder Servo.
2019-05-19T21:08:48.679Z,1558300128.679 [RudderServo](INFO): Powering down
2019-05-19T21:08:48.679Z,1558300128.679 [ThrusterServo](DEBUG): Uninitialize Thruster Servo.
2019-05-19T21:08:48.680Z,1558300128.680 [ThrusterServo](INFO): Powering down
2019-05-19T21:08:48.680Z,1558300128.680 [SBIT](DEBUG): Uninitialize SBIT Component.
2019-05-19T21:08:48.681Z,1558300128.681 [IBIT](DEBUG): Uninitialize IBIT Component.
2019-05-19T21:08:48.681Z,1558300128.681 [CBIT](DEBUG): Uninitialize CBIT Component.
2019-05-19T21:08:48.681Z,1558300128.681 [CBIT](DEBUG): Powering off loads.
2019-05-19T21:08:48.693Z,1558300128.693 [CBIT](DEBUG): Disabling WDT.
2019-05-19T21:08:48.705Z,1558300128.705 [CBIT](DEBUG): Opening all GF detection circuits.
2019-05-19T21:08:48.705Z,1558300128.705 [controlThread ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.750Z,1558300128.750 [Radio_Surface ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.755Z,1558300128.755 [DataOverHttps ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.783Z,1558300128.783 [WetLabsBB2FL ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.870Z,1558300128.870 [CTD_NeilBrown ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.911Z,1558300128.911 [NavChartDb ThreadHandler](INFO): Thread cancelled.
2019-05-19T21:08:48.972Z,1558300128.972 [logger ThreadHandler](INFO): Thread cancelled.