blob: 8ec07042ab569602f4619076b1cb68d1101d5cf8 [file] [log] [blame]
// 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"},
{0x1709, "Number of detected ASRC mem errors"}, // ASRC_FIFO_MEM_ERRORS
{0x170A, "Maximum ASRC mem error size"}, // ASRC_FIFO_ERROR_SIZE
{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)) {}
Diagnostics::~Diagnostics() {
Stop();
}
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