/** \file
 *
 * ESPClient class implementation.
 *
 *  Copyright (c) 2015 MBARI
 *  MBARI Proprietary Information.  All Rights Reserved
 */

#include "ESPClient.h"

#include <errno.h>
#include <assert.h>

/****************************************************************************

State machine for coordinating interactions with the ESP.

The happy-path sequence of operations is as follows:

    - wait for prompt
    - issue showlog and showStatus commands
    - await result (from showStatus)
    - issue loadCartridge cartridge
    - await result(number of selected cartridge)
    - issue startFiltering
    - await result(:FILTERING);
    - await state(PAUSED)
    - If not PAUSED from ESP, check for request for such pause from mission level
    - issue startProcessing
    - await result(:PROCESSING);
    - await state(PROCESSED)
    - issue stop
    - await state(STOPPED)

****************************************************************************/

ESPClient::ESPClient( ESPComm& espComm,
                      Logger& logger,
                      Timespan initialPromptTimeout,
                      Timespan loadCartridgeTimeout,
                      Timespan filterResultTimeout,
                      Timespan processResultTimeout,
                      Timespan stopResultTimeout
                    )

    : espComm_( espComm ),
      logger_( logger ),

      initialPromptTimeout_( initialPromptTimeout ),
      loadCartridgeTimeout_( loadCartridgeTimeout ),
      filterResultTimeout_( filterResultTimeout ),
      processResultTimeout_( processResultTimeout ),
      stopResultTimeout_( stopResultTimeout ),

      stopSamplingRequested_( false ),
      pauseFilteringIssued_( false ),

      debug_( false ),
      samplingState_( S_NONE ),

      cartridge_( "" ),
      partialLine_( "" ),
      samplingError_( "" ),
      latestResult_( 0 ),
      latestException_( 0 )
{
}

ESPClient::~ESPClient()
{
    if( latestResult_ != 0 )
    {
        delete latestResult_;
    }
    if( latestException_ != 0 )
    {
        delete latestException_;
    }
}

bool ESPClient::startSampling( Str cartridge )
{
    if( debug_ )
    {
        logDebug( Str( "--ESPClient::startSampling cartridge='" ) + cartridge + "'--" );
    }

    if( samplingState_ != S_NONE )
    {
        Str error = Str( "startSampling: not at acceptable samplingState_: " ) + samplingStateName( samplingState_ );
        setError( error );
        logError( error );
        return false;
    }

    cartridge_ = cartridge;

    setError( "" );

    startTimeForInitialPrompt_ = Timestamp::Now();
    samplingState_ = S_WAITING_INITIAL_PROMPT;

    if( debug_ )
    {
        logDebug( Str( "startSampling complete; samplingState_=" ) + samplingStateName( samplingState_ ) );
    }

    return true;
}

bool ESPClient::isSampling()
{
    if( samplingState_ != S_NONE && samplingState_ != S_STOPPED && samplingState_ != S_ERROR )
    {
        advanceInteraction();
        return samplingState_ != S_NONE && samplingState_ != S_STOPPED && samplingState_ != S_ERROR;
    }
    else
    {
        return false;
    }
}

void ESPClient::advanceInteraction()
{
    Str line;
    ESPComm::EspStream stream;
    int ret = getLine( line, stream );

    if( ret < 0 )
    {
        // logError already done by getLine.
        setError( Str( "error: getLine returned " ) + ret );
        samplingState_ = S_ERROR;
        return;
    }

    if( ret == 0 )  // no new line...
    {
        if( samplingState_ == S_WAITING_INITIAL_PROMPT && espComm_.getCurrentStream() == ESPComm::PROMPT )
        {
            stream = ESPComm::PROMPT;
            // and let it fall through under this condition
        }
    }

    switch( samplingState_ )
    {
    case S_WAITING_INITIAL_PROMPT:
    {
        if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
            break;
        }

        if( stream == ESPComm::PROMPT )
        {
            issueCommand( "\tshowlog nil, true", 10 );
            samplingState_ = S_PREPARING_SHOW_LOG;
        }
        else if( startTimeForInitialPrompt_.elapsed() >= initialPromptTimeout_ )
        {
            logFault( "Timeout while awaiting prompt" );
            samplingState_ = S_ERROR;
        }

        break;
    }

    case S_PREPARING_SHOW_LOG:
    {
        if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
            break;
        }

        issueCommand( "showStatus", 10 );
        samplingState_ = S_PREPARING_SHOW_STATUS;

        break;
    }

    case S_PREPARING_SHOW_STATUS:
    {
        if( latestResult_ != 0 )  // showStatus does generate a result
        {
            consumeResult();

            Str cmd = "Cmd.loadCartridge";
            if( cartridge_.length() > 0 )
            {
                cmd += " ";
                cmd += cartridge_;
            }

            issueCommand( cmd, loadCartridgeTimeout_ );
            samplingState_ = S_LOADING_CARTRIDGE;
        }
        else if( latestException_ != 0 )
        {
            handleException( true );
        }
        else if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
        }
        else checkCmdResultTimeout();

        break;
    }

    case S_LOADING_CARTRIDGE:
    {
        if( latestResult_ != 0 )
        {
            consumeResult();

            // no explicit complete timeout for Cmd.startFiltering -- indicated by ESP in subsequent result.
            issueCommand( "Cmd.startFiltering", filterResultTimeout_ );
            samplingState_ = S_WAITING_FOR_PRIMING;
        }
        else if( latestException_ != 0 )
        {
            handleException( true );
        }
        else if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
        }
        else checkCmdResultTimeout();

        break;
    }

    case S_WAITING_FOR_PRIMING:
    {
        if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
            break;
        }

        ESPComm::EspState espState = espComm_.getEspState();
        if( espState == ESPComm::ESP_STATE_PRIMING )
        {
            samplingState_ = S_PRIMING;
        }
        else if( latestException_ != 0 )
        {
            handleException( false );
        }
        else checkCmdCompleteTimeout();

        break;
    }

    case S_PRIMING:
    {
        if( latestResult_ != 0 )
        {
            // capture timeout and update cmdCompleteTimeout_
            float timeoutMinutes = -1;
            int parseRes = sscanf( latestResult_->cStr(), "%f", &timeoutMinutes );
            if( parseRes == 1 )
            {
                consumeResult();
                samplingState_ = S_WAITING_FOR_FILTERING;

                logger_.syslog( Str( "Filtering timeoutMinutes=" ) + timeoutMinutes
                                + " issuedCmd_=" + issuedCmd_, Syslog::IMPORTANT );
                double timeoutSeconds = timeoutMinutes * 60;
                cmdCompleteTimeout_ = Timespan( timeoutSeconds );
            }
            else
            {
                Str msg = Str( "In " ) + samplingStateName( samplingState_ ) + ": " +
                          "Couldn't parse filtering timeout expected from ESP." +
                          " Got result: " + *latestResult_;
                logFault( msg );
                samplingState_ = S_ERROR;
            }
        }
        else if( latestException_ != 0 )
        {
            handleException( true );
        }
        else if( stopSamplingRequested_ )
        {
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
        }
        else checkCmdResultTimeout();

        break;
    }

    case S_WAITING_FOR_FILTERING:
    {
        ESPComm::EspState espState = espComm_.getEspState();
        if( espState == ESPComm::ESP_STATE_FILTERING )
        {
            samplingState_ = S_FILTERING;
        }
        else if( latestException_ != 0 )
        {
            handleException( false );
        }
        else if( stopSamplingRequested_ )
        {
            // ESP is not FILTERING yet, so:
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.stop" ), Syslog::IMPORTANT );
            issueStopCommand();
        }
        else checkCmdCompleteTimeout();

        break;
    }

    case S_FILTERING:
    {
        if( latestResult_ != 0 )
        {
            // No result expected.  Last result should have happened (and been consumed) in S_PRIMING.

            Str msg = Str( " No result expected in " ) + samplingStateName( samplingState_ ) + "." +
                      " Got: " + *latestResult_;
            logFault( msg );
            consumeResult();
            samplingState_ = S_ERROR;
            stopSamplingRequested_ = false;
        }
        else if( latestException_ != 0 )
        {
            handleException( true );
        }
        else
        {
            samplingState_ = S_WAITING_FOR_PAUSED;
        }

        break;
    }

    case S_WAITING_FOR_PAUSED:
    {
        ESPComm::EspState espState = espComm_.getEspState();
        if( espState == ESPComm::ESP_STATE_PAUSED )
        {
            samplingState_ = S_PAUSED;
        }
        else if( latestException_ != 0 )
        {
            handleException( false );
        }
        else if( stopSamplingRequested_ && !pauseFilteringIssued_ )
        {
            // ESP is currently filtering.
            // Request pauseFiltering to trigger "immediate" continuation to next sample states:
            logger_.syslog( Str( "Stop sampling requested. Issuing Cmd.pauseFiltering" ), Syslog::IMPORTANT );
            issueCommand( "Cmd.pauseFiltering", filterResultTimeout_ );
            pauseFilteringIssued_ = true;
        }
        else checkCmdCompleteTimeout();

        break;
    }

    case S_PAUSED:
    {
        // no explicit complete timeout for Cmd.startProcessing -- indicated by ESP in subsequent result.

        if( pauseFilteringIssued_ )
        {
            // In this case, expect a result
            if( latestResult_ != 0 )
            {
                logger_.syslog( Str( "In S_PAUSED received result: " ) + *latestResult_, Syslog::IMPORTANT );
                consumeResult();
                issueCommand( "Cmd.startProcessing", processResultTimeout_ );
                samplingState_ = S_PROCESSING;
            }
            else if( latestException_ != 0 )
            {
                handleException( true );
            }
            else checkCmdResultTimeout();
        }
        else
        {
            // just request processing right away
            issueCommand( "Cmd.startProcessing", processResultTimeout_ );
            samplingState_ = S_PROCESSING;
        }

        break;
    }

    case S_PROCESSING:
    {
        if( latestResult_ != 0 )
        {
            // capture timeout and update cmdCompleteTimeout_
            float timeoutMinutes = -1;
            int parseRes = sscanf( latestResult_->cStr(), "%f", &timeoutMinutes );
            if( parseRes == 1 )
            {
                consumeResult();
                samplingState_ = S_WAITING_FOR_PROCESSED;

                // now set cmdCompleteTimeout_ for the ongoing processing command
                logger_.syslog( Str( "Processing timeoutMinutes=" ) + timeoutMinutes
                                + " issuedCmd_=" + issuedCmd_, Syslog::IMPORTANT );
                double timeoutSeconds = timeoutMinutes * 60;
                cmdCompleteTimeout_ = Timespan( timeoutSeconds );
            }
            else
            {
                Str msg = Str( "In " ) + samplingStateName( samplingState_ ) + ": " +
                          "Couldn't parse processing timeout expected from ESP." +
                          " Got result: " + *latestResult_;
                logFault( msg );
                samplingState_ = S_ERROR;
            }
        }
        else if( latestException_ != 0 )
        {
            handleException( true );
        }
        else checkCmdResultTimeout();

        break;
    }

    case S_WAITING_FOR_PROCESSED:
    {
        ESPComm::EspState espState = espComm_.getEspState();
        if( espState == ESPComm::ESP_STATE_PROCESSED )
        {
            issueStopCommand();
        }
        else if( latestException_ != 0 )
        {
            handleException( false );
        }
        else checkCmdCompleteTimeout();

        break;
    }

    case S_STOPPING:
    {
        stopSamplingRequested_ = false;
        if( latestResult_ != 0 )
        {
            consumeResult();

            samplingState_ = S_STOPPED;
        }
        else if( latestException_ != 0 )
        {
            handleException( true, false );
        }
        else checkCmdResultTimeout( false );

        break;
    }

    case S_STOPPED:
    {
        logError( "advanceInteraction not expected to be called in S_STOPPED state. please report this bug." );
        break;
    }

    default:
        logError( Str( "invalid samplingState_=" ) + samplingState_ + ". please report this bug." );
    }
}


bool ESPClient::isSuccessfulSampling()
{
    return samplingError_.length() == 0;
}

Str ESPClient::getSamplingError()
{
    return samplingError_;
}

void ESPClient::issueCommand( Str cmd, Timespan resultTimeout, Timespan completeTimeout )
{
    espComm_.sendLine( cmd.cStr() );
    cmdIssueTime_ = Timestamp::Now();
    cmdResultTimeout_ = resultTimeout;
    cmdCompleteTimeout_ = completeTimeout;
    issuedCmd_ = cmd;

    if( debug_ ) logDebug( Str( "issueCommand: cmd='" ) + espComm_.escape( cmd.cStr() ) + "'" );
}

void ESPClient::issueStopCommand()
{
    issueCommand( "Cmd.stop", stopResultTimeout_ );
    samplingState_ = S_STOPPING;
    stopSamplingRequested_ = false;
}

void ESPClient::checkCmdResultTimeout( bool issueStop )
{
    if( cmdIssueTime_.elapsed() >= cmdResultTimeout_ )
    {
        Str cmd = espComm_.escape( issuedCmd_.cStr() );
        Str error = Str( "Timeout while awaiting result for cmd='" ) + cmd + "'";
        setError( error );
        logFault( error );

        if( issueStop )
        {
            issueStopCommand();
        }
        else
        {
            samplingState_ = S_ERROR;
            stopSamplingRequested_ = false;
        }
    }
}

void ESPClient::checkCmdCompleteTimeout( bool issueStop )
{
    if( cmdIssueTime_.elapsed() >= cmdCompleteTimeout_ )
    {
        Str cmd = espComm_.escape( issuedCmd_.cStr() );
        Str error = Str( "Timeout while awaiting completion of cmd='" ) + cmd + "'";
        setError( error );
        logFault( error );

        if( issueStop )
        {
            issueStopCommand();
        }
        else
        {
            samplingState_ = S_ERROR;
        }
    }
}

void ESPClient::consumeResult()
{
    if( latestResult_ != 0 )
    {
        if( debug_ )
        {
            Str cmd = espComm_.escape( issuedCmd_.cStr() );
            Timespan elapsed = cmdIssueTime_.elapsed();
            const char* stateName = samplingStateName( samplingState_ );
            Str msg = Str( "In " ) + stateName + ", for cmd='" + cmd
                      + "', consuming result: <<" + espComm_.escape( latestResult_->cStr() )
                      + ">> which took " + elapsed.toString();
            logDebug( msg );
        }

        delete latestResult_;
        latestResult_ = 0;
    }
}

void ESPClient::handleException( bool awaitingResult, bool issueStop )
{
    if( latestException_ != 0 )
    {
        Str cmd = espComm_.escape( issuedCmd_.cStr() );
        Timespan elapsed = cmdIssueTime_.elapsed();
        const char* stateName = samplingStateName( samplingState_ );
        Str msg = Str( "In state " ) + stateName + " got exception while awaiting "
                  + ( awaitingResult ? "result for" : "completion of" )
                  + " cmd='" + cmd + "'"
                  + " exception=<<" + latestException_->cStr() + ">>."
                  + " Elapsed time since command issued: " + elapsed.toString();
        logError( msg );
        setError( msg );

        delete latestException_;
        latestException_ = 0;

        if( issueStop )
        {
            issueStopCommand();
        }
        else
        {
            samplingState_ = S_ERROR;
            stopSamplingRequested_ = false;
        }
    }
}

void ESPClient::setError( Str error )
{
    if( samplingError_.length() == 0 )  //  only capture the first one
    {
        samplingError_ = error;
    }
    else if( debug_ )
    {
        logDebug( Str( "setting error='" ) + error + "' but keeping initial error='" + samplingError_ + "'" );
    }
}

int ESPClient::getLine( Str& line, ESPComm::EspStream& stream )
{
    char response[1024];
    stream = ESPComm::UNKNOWN;
    int len = espComm_.readLine( response, sizeof( response ), &stream );

    if( len <= -2 )  // actual error in readLine
    {
        logError( Str( "Error reading line from ESP: len=" ) + len + " (see stderr for error message)" );
        return len;
    }

    int ret = 0;  // assume still waiting for line.

    if( len > 0 )  // we got data
    {
        if( response[len - 1] == '\n' )  // we got a new line
        {
            // do not include trailing \n in reported line:
            line = partialLine_ + Str( response, len - 1 );
            partialLine_ = "";

            if( debug_ )
            {
                Str escaped = espComm_.escape( line.cStr(), line.length() );
                Str msg = Str( ":-<: " ) + ESPComm::StreamName( stream ) + " \"" + escaped + "\"";
                logDebug( msg );
            }

            ret = +1;  // ok, we got a line
        }
        else
        {
            partialLine_ += Str( response, len );
        }
    }
    // else: (len == 0 || len == -1) => still waiting for line.

    // before returning, did we get a new complete result or exception?
    if( stream == ESPComm::RESULT )
    {
        Str* result = espComm_.getLastResult();
        if( result != 0 )
        {
            if( latestResult_ != 0 )
            {
                logError( Str( "WARN: previous result was not consumed: <<\n" ) + latestResult_->cStr() + ">>" );
                delete latestResult_;
            }
            latestResult_ = result;
        }
    }

    else if( stream == ESPComm::EXCEPTION )
    {
        Str* exception = espComm_.getLastException();
        if( exception != 0 )
        {
            if( latestException_ != 0 )
            {
                logError( Str( "WARN: previous exception was not consumed: <<" ) + latestException_->cStr() + ">>" );
                delete latestException_;
            }
            latestException_ = exception;
        }
    }

    return ret;
}

void ESPClient::logDebug( Str msg )
{
    logger_.syslog( Str( "ESPClient: " ) + msg, Syslog::DEBUG );
    //printf( "DEBUG: %s\n", msg.cStr() );
}

void ESPClient::logError( Str msg )
{
    logger_.syslog( msg, Syslog::ERROR );
    //printf( "ERROR: %s\n", msg.cStr() );
}

void ESPClient::logFault( Str msg )
{
    logger_.syslog( msg, Syslog::FAULT );
    //printf( "FAULT: %s\n", msg.cStr() );
}