src/diagnostics.cc

// Copyright 2017 The Chromium OS Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "diagnostics.h"

#include <string>

#include <base/bind.h>
#include <base/callback.h>
#include <base/logging.h>
#include <base/macros.h>
#include <base/stl_util.h>
#include <base/strings/string_number_conversions.h>
#include <base/strings/stringprintf.h>

#include "util.h"

namespace atrusctl {

namespace {

using QueryResult = HIDRawDevice::QueryResult;

const uint16_t kCommandDaisySlaves = 0x1351;
const uint16_t kCommandDfuStatus = 0x1500;
const uint16_t kCommandHookStatus = 0x1601;
const uint16_t kCommandStateUptime = 0x1604;
const uint16_t kCommandMicSelected = 0x1706;
const uint16_t kCommandSpkSelected = 0x1707;
const uint16_t kCommandSpkAudio = 0x1708;

const Diagnostics::DiagCommand kCommands[] = {
    {kCommandDaisySlaves, "Number of connected slaves"},  // DAISY_NUM_SLAVES
    {kCommandDfuStatus, "DFU status"},                    // DAISY_DFU_STATUS
    {0x1600, "Mute status"},                              // STATE_MUTED
    {kCommandHookStatus, "Hook status"},                  // STATE_HOOK_OFF
    {0x1602, "Volume"},                                   // STATE_VOLUME
    {0x1603, "LED status"},                               // STATE_LED
    {kCommandStateUptime, "Device uptime seconds"},       // STATE_UPTIME
    {0x1605, "SHARC status"},                             // STATE_SHARC_ALIVE
    {kCommandMicSelected, "Mic selected"},
    {kCommandSpkSelected, "Speaker selected"},
    {kCommandSpkAudio, "Speaker audio"},
    {0x5000, "Touch register status"},  // TOUCH_REGISTER_STATUS
    {0x5001, "SPI queue status"},       // SPI_QUEUE_STATUS
    {0x5004, "Button presses"},         // NR_BUTTON_PRESSES
};

const Diagnostics::DiagCommand kCommandsTrueVoice[] = {
    {0x1804, ""},  // TV_ERLE_MAX
    {0x1805, ""},  // TV_ERLE_MEAN
    {0x1806, ""},  // TV_ERLE_VARIANCE
    {0x1807, ""},  // TV_FEEDBACK_EST_MIN
    {0x1808, ""},  // TV_FEEDBACK_EST_MAX
    {0x1809, ""},  // TV_FEEDBACK_EST_MEAN
    {0x180A, ""},  // TV_FEEDBACK_EST_VARIANCE
    {0x180B, ""},  // TV_NR_MIN
    {0x180C, ""},  // TV_NR_MAX
    {0x180D, ""},  // TV_NR_MEAN
    {0x180E, ""},  // TV_NR_VARIANCE
    {0x180F, ""},  // TV_MIC_AVE_MIN
    {0x1810, ""},  // TV_MIC_AVE_MAX
    {0x1811, ""},  // TV_MIC_AVE_MEAN
    {0x1812, ""},  // TV_MIC_AVE_VARIANCE
    {0x1813, ""},  // TV_LS_NOISE_MIN
    {0x1814, ""},  // TV_LS_NOISE_MAX
    {0x1815, ""},  // TV_LS_NOISE_MEAN
    {0x1816, ""},  // TV_LS_NOISE_VARIANCE
    {0x1817, ""},  // TV_MIC_NOISE_MIN
    {0x1818, ""},  // TV_MIC_NOISE_MAX
    {0x1819, ""},  // TV_MIC_NOISE_MEAN
    {0x181A, ""},  // TV_MIC_NOISE_VARIANCE
};

const Diagnostics::DiagCommand kCommandsExtended[] = {
    {0x1300, "VERSION_MASTER"},       // VERSION_MASTER
    {0x1310, "VERSION_SLAVE1_UP"},    // VERSION_SLAVE1_UP
    {0x1311, "VERSION_SLAVE2_UP"},    // VERSION_SLAVE2_UP
    {0x1312, "VERSION_SLAVE3_UP"},    // VERSION_SLAVE3_UP
    {0x1313, "VERSION_SLAVE4_UP"},    // VERSION_SLAVE4_UP
    {0x1314, "VERSION_SLAVE1_DOWN"},  // VERSION_SLAVE1_DOWN
    {0x1315, "VERSION_SLAVE2_DOWN"},  // VERSION_SLAVE2_DOWN
    {0x1316, "VERSION_SLAVE3_DOWN"},  // VERSION_SLAVE3_DOWN
    {0x1317, "VERSION_SLAVE4_DOWN"},  // VERSION_SLAVE4_DOWN
    {0x1350, "DAISY_MIN_VERSION"},    // DAISY_MIN_VERSION
    {0x1352, "DAISY_POWER"},          // DAISY_POWER
    {0x1700, "HW_ID"},                // HW_ID
    {0x1702, "MIC_CALIBRATION"},      // MIC_CALIBRATION
    {0x1703, "BOOT_PARTITION"},       // BOOT_PARTITION
    {0x5002,
     "TOUCH_ANALOG_CALIBRATION_STATUS"},  // TOUCH_ANALOG_CALIBRATION_STATUS
    {0x5003, "RF_NOISE_DETECTION"},       // RF_NOISE_DETECTION
};

const Diagnostics::DiagCommand kCommandsPoll[] = {
    {kCommandDaisySlaves, "Number of connected slaves"},
    {kCommandDfuStatus, "DFU status"},
    {kCommandHookStatus, "Hook status"},
    {kCommandMicSelected, "Mic selected"},
    {kCommandSpkSelected, "Speaker selected"},
    {kCommandSpkAudio, "Speaker audio"},
};

// TODO(karl@limesaudio.com): Remove this when fixed in firmware
const int64_t kDiagDelay = 10;

const int kPollIntervalSeconds = 5;

// Expected response when querying an Atrus device with the command
// |kCommandHookStatus| is either "Offhook" or "Onhook". We check for this
// string and assume the status is "Onhook" if the condition is false.
const char kCallOffHook[] = "Offhook";

// Because this is used to parse a string containing a number and trailing
// characters, check |new_value| rather than the return value of
// base::StringToInt to determine if a value was read.
bool ParseIntFromResponseBody(const std::string& str, int* val) {
  int new_value = -1;
  base::StringToInt(str, &new_value);
  if (new_value == -1) {
    LOG(ERROR) << "Failed to parse int from response: " << str;
    return false;
  }

  *val = new_value;
  return true;
}

}  // namespace

Diagnostics::Diagnostics()
    : commands_(kCommands, kCommands + arraysize(kCommands)),
      commands_extended_(kCommandsExtended,
                         kCommandsExtended + arraysize(kCommandsExtended)),
      commands_poll_(kCommandsPoll, kCommandsPoll + arraysize(kCommandsPoll)),
      commands_truevoice_(kCommandsTrueVoice,
                          kCommandsTrueVoice + arraysize(kCommandsTrueVoice)) {}

void Diagnostics::Start(const base::TimeDelta& diag_interval,
                        const base::TimeDelta& ext_diag_interval,
                        const std::string& device_path) {
  if (diag_timer_.IsRunning()) {
    LOG(INFO) << "Diagnostics started while already running";
    diag_timer_.Stop();
    poll_timer_.Stop();
  }

  ResetSessionState();
  ext_diag_interval_ = ext_diag_interval;
  // Perform an extended diagnostic the first time
  last_extended_diag_time_ = base::TimeTicks();

  device_.set_path(device_path);

  poll_timer_.Start(FROM_HERE,
                    base::TimeDelta::FromSeconds(kPollIntervalSeconds),
                    base::Bind(&Diagnostics::Poll, base::Unretained(this)));

  // Run a diagnostic immediately, then do it periodically
  Run();
  diag_timer_.Start(FROM_HERE,
                    diag_interval,
                    base::Bind(&Diagnostics::Run, base::Unretained(this)));
}

void Diagnostics::Stop() {
  if (diag_timer_.IsRunning()) {
    diag_timer_.Stop();
  }
  if (poll_timer_.IsRunning()) {
    poll_timer_.Stop();
  }
}

void Diagnostics::Run() {
  LOG(INFO) << "-- Report start --";
  const base::TimeTicks now = base::TimeTicks::Now();
  QueryDeviceWithCommands(commands_);

  // If a call is active, log TrueVoice parameters
  if (call_status_.find(kCallOffHook) != std::string::npos) {
    VLOG(1) << "Internal TrueVoice parameters: ";
    QueryDeviceWithCommands(commands_truevoice_);
  }

  if (now - last_extended_diag_time_ > ext_diag_interval_) {
    should_do_extended_diagnose_ = true;
  }

  if (should_do_extended_diagnose_) {
    should_do_extended_diagnose_ = false;
    last_extended_diag_time_ = now;
    LOG(INFO) << "-- Extended report --";
    QueryDeviceWithCommands(commands_extended_);
    LOG(INFO) << "Number of USB devices connected: "
              << number_of_connected_devices_;
  }
  LOG(INFO) << "-- Report end --";
}

void Diagnostics::Poll() {
  for (const DiagCommand& command : commands_poll_) {
    device_.Query(command.id,
                  base::Bind(&Diagnostics::HandlePollQueryResult,
                             base::Unretained(this),
                             command.description));
    // Workaround for firmware < v0.7.0
    // TODO(karl@limesaudio.com): Remove this when fixed in firmware
    // TODO(karl@limesaudio.com) Update: Due to issues with USB performance
    // for fast volume events, keep this until we can verify that it does not
    // stress the Atrus further
    TimeoutMs(kDiagDelay);
  }
}

void Diagnostics::QueryDeviceWithCommands(
    const std::vector<DiagCommand>& commands) {
  for (const DiagCommand& command : commands) {
    // This check is to see when the TV parameters are about to be read,
    // (starting at 0x1804) and in that case prepend the below line for more
    // readability in the log
    device_.Query(command.id,
                  base::Bind(&Diagnostics::HandleQueryResult,
                             base::Unretained(this),
                             command.description));
    // Workaround for firmware < v0.7.0
    // TODO(karl@limesaudio.com): Remove this when fixed in firmware
    // TODO(karl@limesaudio.com) Update: Due to issues with USB performance
    // for fast volume events, keep this until we can verify that it does not
    // stress the Atrus further
    TimeoutMs(kDiagDelay);
  }
}

void Diagnostics::LogResponse(const std::string& cmd_desc,
                              const HIDMessage& response) {
  if (VLOG_IS_ON(1)) {
    LOG(INFO) << cmd_desc << " " << response.ToString();
  } else {
    LOG(INFO) << response.ToString();
  }
}

void Diagnostics::LogQueryError(QueryResult code, const HIDMessage& request) {
  switch (code) {
    case QueryResult::kQueryUnknownResponse:
      LOG(INFO) << base::StringPrintf("0x%04X: Error: unknown response",
                                      request.command_id());
      break;
    case QueryResult::kQueryError:
      LOG(INFO) << base::StringPrintf("0x%04X: Error: report failed",
                                      request.command_id());
      break;
    case QueryResult::kQueryTimeout:
      LOG(INFO) << base::StringPrintf("0x%04X: Error: timeout",
                                      request.command_id());
      break;
    case QueryResult::kQuerySuccess:
    default:
      LOG(INFO) << base::StringPrintf("0x%04X: Unhandled error",
                                      request.command_id());
      break;
  }
}

void Diagnostics::HandleQueryResult(const std::string& cmd_desc,
                                    QueryResult code,
                                    const HIDMessage& request,
                                    const HIDMessage& response) {
  if (code != QueryResult::kQuerySuccess) {
    return LogQueryError(code, request);
  }

  LogResponse(cmd_desc, response);

  int new_value;
  switch (response.command_id()) {
    case kCommandStateUptime:
      if (ParseIntFromResponseBody(response.body(), &new_value)) {
        UpdateUptime(new_value);
      }
      break;
    case kCommandDaisySlaves:
      if (ParseIntFromResponseBody(response.body(), &new_value)) {
        // Ignore return value here, since we aready logged the response above.
        // This is just to make sure the value is updated.
        UpdateNumberOfConnectedSlaves(new_value);
      }
      break;
  }
}

void Diagnostics::HandlePollQueryResult(const std::string& cmd_desc,
                                        QueryResult code,
                                        const HIDMessage& request,
                                        const HIDMessage& response) {
  // Only log these if their values changed since the last poll.
  switch (response.command_id()) {
    case kCommandMicSelected:
      if (mic_selected_ != response.body()) {
        LogResponse(cmd_desc, response);
      }
      mic_selected_ = response.body();
      break;
    case kCommandSpkSelected:
      if (spk_selected_ != response.body()) {
        LogResponse(cmd_desc, response);
      }
      spk_selected_ = response.body();
      break;
    case kCommandSpkAudio:
      if (spk_silence_ != response.body()) {
        LogResponse(cmd_desc, response);
      }
      spk_silence_ = response.body();
      break;
    case kCommandHookStatus:
      if (call_status_ != response.body()) {
        LogResponse(cmd_desc, response);
      }
      call_status_ = response.body();
      break;
    case kCommandDfuStatus:
      if (dfu_status_ != response.body()) {
        LogResponse(cmd_desc, response);
      }
      dfu_status_ = response.body();
      break;
    case kCommandDaisySlaves:
      int new_value;
      if (ParseIntFromResponseBody(response.body(), &new_value)) {
        if (UpdateNumberOfConnectedSlaves(new_value)) {
          LogResponse(cmd_desc, response);
        }
      }
      break;
  }
}

void Diagnostics::UpdateNumberOfDevices(int new_value) {
  if (new_value != number_of_connected_devices_) {
    should_do_extended_diagnose_ = true;
  }
  number_of_connected_devices_ = new_value;
}

void Diagnostics::UpdateUptime(int new_value) {
  if (new_value < uptime_) {
    should_do_extended_diagnose_ = true;
  }
  uptime_ = new_value;
}

bool Diagnostics::UpdateNumberOfConnectedSlaves(int new_value) {
  if (new_value != number_of_connected_slaves_) {
    should_do_extended_diagnose_ = true;
    number_of_connected_slaves_ = new_value;
    return true;
  }
  return false;
}

void Diagnostics::ResetSessionState() {
  uptime_ = 0;
  number_of_connected_slaves_ = 0;
  // don't reset |number_of_connected_devices_|, it's updated on udev events
  mic_selected_.clear();
  spk_selected_.clear();
  spk_silence_.clear();
  // Assume that were in a call when starting up/restarting, so we always
  // log everything on the first diagnostic report
  call_status_ = kCallOffHook;
}

}  // namespace atrusctl