TSTLogger.cc

/******************************************************************************
 * Copyright (c) 2000-2016 Ericsson Telecom AB
 * All rights reserved. This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License v1.0
 * which accompanies this distribution, and is available at
 * http://www.eclipse.org/legal/epl-v10.html
 *
 * Contributors:
 *   Balasko, Jeno
 *   Delic, Adam
 *   Pilisi, Gergely
 *
 ******************************************************************************/
#include "ILoggerPlugin.hh"
#include "TSTLogger.hh"

#ifndef TITAN_RUNTIME_2
#include "RT1/TitanLoggerApi.hh"
#else
#include "RT2/TitanLoggerApi.hh"
#endif

#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <errno.h>
#include <string.h>
#include <netdb.h>
#include <sys/select.h>
#include <sys/types.h>
#include <netinet/in.h>
#include <sys/socket.h>
#include <arpa/inet.h>
#include <sys/time.h>

#include <iostream>
#include <sstream>

#ifdef __cplusplus
extern "C"
{
  ILoggerPlugin *create_plugin() { return new TSTLogger(); }
  void destroy_plugin(ILoggerPlugin *plugin) { delete plugin; }
}
#endif

using namespace std;

////////////////////////////////////////////////////////////////////////////////

class SocketException
{
  string error_msg;
  string reason;
public:
  SocketException(const string p_error_msg, const string p_reason=""):error_msg(p_error_msg),reason(p_reason) {}
  const string getMessage() const { return error_msg; }
  const string getReason() const { return reason; }
};

class TimeoutException : public SocketException
{
public:
  TimeoutException(const string p_error_msg): SocketException(p_error_msg) {}
};

////////////////////////////////////////////////////////////////////////////////

class TCPClient
{
  int socket_fd;
  time_t timeout_time;

  enum select_readwrite_t { SELECT_READ, SELECT_WRITE };
  void wait_for_ready(time_t end_time, select_readwrite_t readwrite);
public:
  TCPClient(): socket_fd(-1), timeout_time(30) {}
  // opens connection and returns socket file descriptor, throws exception on error
  void open_connection(const string host_name, const string service_name) throw(SocketException);
  // send a string to a socket, don't return until the whole string is sent
  void send_string(const string& str) throw(SocketException);
  // receive available data to the end of the parameter string, blocks until at least wait_for_bytes chars have arrived,
  // returns false if connection was closed
  bool receive_string(string& str, const size_t wait_for_bytes) throw(SocketException);
  // close connection
  void close_connection() throw(SocketException);
  time_t get_timeout() const { return timeout_time; }
  void set_timeout(time_t t) { timeout_time = t; }
};

void TCPClient::open_connection(const string host_name, const string service_name) throw(SocketException)
{
  if (socket_fd!=-1) {
    close_connection();
  }
  struct addrinfo *res, *aip;
  struct addrinfo hints;
  memset(&hints, 0, sizeof(hints));
  hints.ai_socktype = SOCK_STREAM;
  int status = getaddrinfo(host_name.c_str(), service_name.c_str(), &hints, &res);
  if (status!=0) {
    throw SocketException("Cannot find host and service", gai_strerror(status));
  }
  for (aip = res; aip != NULL; aip = aip->ai_next) {
    // create socket descriptor
    socket_fd = socket(aip->ai_family, aip->ai_socktype, aip->ai_protocol);
    if (socket_fd==-1) continue;
    // try to connect
    status = connect(socket_fd, aip->ai_addr, aip->ai_addrlen);
    if (status==0) break; // connected
  }
  freeaddrinfo(res);
  if (aip==NULL) {
    socket_fd = -1;
    throw SocketException("Cannot connect to host and service");
  }
}

void TCPClient::close_connection() throw(SocketException)
{
  if (socket_fd==-1) {
    return;
  }
  int rv = close(socket_fd);
  socket_fd = -1;
  if (rv!=0) {
    throw SocketException("Cannot close socket", strerror(errno));
  }
}

// end_time - is time in seconds (from time(NULL)+timeout, when should we give up waiting
// readwrite - are we checking for read or write readyness on the file descriptor
void TCPClient::wait_for_ready(time_t end_time, select_readwrite_t readwrite)
{
  struct timeval tv;
  tv.tv_sec = end_time - time(NULL);
  tv.tv_usec = 0;
  fd_set fds;
wait_reset:
  FD_ZERO(&fds);
  FD_SET(socket_fd, &fds);
  int status = select(socket_fd+1,
                (readwrite==SELECT_READ)  ? &fds : NULL, 
                (readwrite==SELECT_WRITE) ? &fds : NULL,
                NULL, &tv);
  if (status==-1) {
    if (errno==EINTR) { // some signal
      // update time
      tv.tv_sec = end_time - time(NULL);
      tv.tv_usec = 0;
      goto wait_reset; // wait again
    }
    throw SocketException("Error while waiting on socket", strerror(errno));
  }
  if (FD_ISSET(socket_fd, &fds)==0) {
    throw TimeoutException("Timeout while waiting on socket");
  }
}

void TCPClient::send_string(const string& str) throw(SocketException)
{
  if (socket_fd==-1) {
    throw SocketException("Connection is not open");
  }
  time_t end_time = time(NULL) + timeout_time;
  size_t sent_cnt = 0;
  size_t str_len = str.size();
  while (sent_cnt<str_len) {
    wait_for_ready(end_time, SELECT_WRITE);
    ssize_t n = send(socket_fd, str.c_str()+sent_cnt, str_len-sent_cnt, 0);
    if (n==-1) {
      throw SocketException("Cannot send data on socket", strerror(errno));
    }
    sent_cnt += n;
  }
}

// wait_for_bytes - wait until at least so many bytes arrived or timeout or connection closed,
//                  if zero then wait until connection is closed
bool TCPClient::receive_string(string& str, const size_t wait_for_bytes) throw(SocketException)
{
  if (socket_fd==-1) {
    throw SocketException("Connection is not open");
  }
  time_t end_time = time(NULL) + timeout_time;
  bool open = true;
  char buff[1024];
  size_t bytes_received = 0;
  while (wait_for_bytes==0 || bytes_received<wait_for_bytes) {
    wait_for_ready(end_time, SELECT_READ);
    ssize_t recv_cnt = recv(socket_fd, buff, sizeof(buff), 0);
    if (recv_cnt==-1) {
        throw SocketException("Cannot read data from socket", strerror(errno));
    }
    if (recv_cnt==0) { // socket was closed by the other side
      open = false;
      close_connection();
      break;
    }
    bytes_received += recv_cnt;
    // store received data
    str.append(buff, recv_cnt);
  }
  return open;
}

////////////////////////////////////////////////////////////////////////////////

class HttpException : public SocketException
{
public:
  HttpException(const string p_error_msg, const string p_reason=""):
    SocketException(p_error_msg, p_reason) {}
};

typedef map<string,string> string_map;

class HTTPClient : public TCPClient
{
public:
  HTTPClient(): TCPClient() {}
  string url_encode(const string& str);
  string post_request(const string& host, const string& uri, const string& user_agent, const string_map& req_params) throw(SocketException);
};

string HTTPClient::url_encode(const string& str)
{
  static char hex[] = "0123456789abcdef";
  stringstream ss;
  for (size_t i=0; i<str.size(); i++) {
    char c = str[i];
    if (isalnum(c) || c=='-' || c=='_' || c=='.' || c=='~') {
      ss << c;
    } else if (c==' ') {
      ss << '+';
    } else {
      ss << '%' << hex[(c>>4) & 15] << hex[(c&15) & 15];
    }
  }
  return ss.str();
}

string HTTPClient::post_request(const string& host, const string& uri, const string& user_agent, const string_map& req_params) throw(SocketException)
{
  // compose request message
  stringstream req_ss;
  req_ss << "POST " << uri << " HTTP/1.1\r\n" << // Host: must be added if HTTP/1.1 is used
    "Host: " << host << "\r\n" <<
    "User-Agent: " << user_agent << "\r\n" <<
    "Connection: Close" << "\r\n" <<
    "Content-Type: application/x-www-form-urlencoded" << "\r\n"; // as if it were post'ed from a web browser html form
  stringstream req_body_ss;
  for (string_map::const_iterator it = req_params.begin(); it!=req_params.end(); ++it) {
    if (it!=req_params.begin()) req_body_ss << '&';
    req_body_ss << url_encode(it->first) << '=' << url_encode(it->second);
  }
  req_ss << "Content-Length: " << req_body_ss.str().size() << "\r\n";
  req_ss << "\r\n" << req_body_ss.str();
  // send request
  //cerr << "HTTP POST REQUEST:\n[" << req_ss.str() << "]\n";
  send_string(req_ss.str());
  // receive response, wait until the server closes the connection (doesn't work with Keep-Alive!)
  string response;
  receive_string(response, 0); // receive until connection is closed by the peer or timeout
  //cerr << "HTTP POST RESPONSE:\n[" << response << "]\n";
  // divide into header and body parts
  size_t pos = response.find("\r\n\r\n");
  if (pos==string::npos) {
    throw HttpException("Invalid HTTP response", "Cannot find body part");
  }
  string head = response.substr(0, pos);
  string body = response.substr(pos+4, string::npos);
  if (head.find("Transfer-Encoding: chunked")!=string::npos) {
    // remove chunked encoding stuff from body
    // FIXME: this doesn't work if the chunks contain \r\n
    string real_body;
    string line;
    bool chunk_line = false;
    for (size_t idx = 0; idx<body.size()-1; idx++) {
      if (body[idx]=='\r' && body[idx+1]=='\n') { // end of line
        if (chunk_line) {
          real_body += line;
        } else {
          if (line=="0") {
            break;
          }
        }
        chunk_line = !chunk_line;
        line = "";
        idx++; 
      } else {
        line += body[idx];
      }
    }
    body = real_body;
  }
  return body;
}

////////////////////////////////////////////////////////////////////////////////


string TSTLogger::get_tst_time_str(const TitanLoggerApi::TimestampType& timestamp)
{
  long long int t = timestamp.seconds().get_long_long_val() * 1000 + timestamp.microSeconds().get_long_long_val() / 1000;
  stringstream s;
  s << (long int)t;
  return s.str();
}

string TSTLogger::get_host_name()
{
  char name[257];
  int status = gethostname(name, 256);
  if (status!=0) return "DefaultExecutingHost";
  return name;
}

string TSTLogger::get_user_name()
{
  return getlogin();
}

TSTLogger::TSTLogger()
{
  this->major_version_ = 1;
  this->minor_version_ = 0;
  this->name_ = mputstr(this->name_, "TSTLogger");
  this->help_ = mputstr(this->help_, "TITAN Logger Plugin for TestStatistics");

  // parameters of this plugin
  parameters["tst_host_name"] = ParameterData("eta-teststatistics.rnd.ki.sw.ericsson.se", true, "TestStatistics web service host name");
  parameters["tst_service_name"] = ParameterData("http", true, "TestStatistics web service name or port number");

  parameters["tst_tcstart_url"] = ParameterData("/ts-rip/rip/tcstart");
  parameters["tst_tcstop_url"] = ParameterData("/ts-rip/rip/tcstop");
  parameters["tst_tsstart_url"] = ParameterData("/ts-rip/rip/tsstart");
  parameters["tst_tsstop_url"] = ParameterData("/ts-rip/rip/tsstop");
  parameters["tst_tcfailreason_url"] = ParameterData("/ts-rip/rip/tcfailreason");

  parameters["dbsUrl"] = ParameterData("esekilx0007-sql5.rnd.ki.sw.ericsson.se:3314", true, "database URL");
  parameters["dbUser"] = ParameterData("demo", true, "database user");
  parameters["dbPass"] = ParameterData("demo", true, "plain text password of the user");
  parameters["dbName"] = ParameterData("teststatistics_demo", true, "name of the database");

  parameters["log_plugin_debug"] = ParameterData("0");

  parameters["testConfigName"] = ParameterData("DefaultConfigName", false, "name of this specific configuration of the test suite");
  parameters["suiteName"] = ParameterData("DefaultSuiteName", false, "name of test suite");
  parameters["executingHost"] = ParameterData(get_host_name(), true, "host where the test was executed");
  parameters["sutId"] = ParameterData("0.0.0.0", true, "IP address of SUT");
  parameters["sutName"] = ParameterData("DefaultSUTName", true, "name of SUT");
  parameters["lsvMajor"] = ParameterData("1", true, "major version number of SUT");
  parameters["lsvMinor"] = ParameterData("0", true, "minor version number of SUT");
  parameters["runByUser"] = ParameterData(get_user_name(), true, "name of user running the tests");
  parameters["projectName"] = ParameterData("DefaultProjectname", true, "name of the project");
  parameters["productName"] = ParameterData("DefaultProductName", true, "name of the product");
  parameters["productVersion"] = ParameterData("0.0", true, "version of the product");
  parameters["configType"] = ParameterData("configType", true, "");
  parameters["configVersion"] = ParameterData("configVersion", true, "");
  parameters["testType"] = ParameterData("testType", true, "");
  parameters["logLink"] = ParameterData("default_log_location", false, "absolute location of log files");
  parameters["logEnd"] = ParameterData("default_web_log_dir", false, "log directory relative to web server root");
  parameters["reportEmail"] = ParameterData(get_user_name()+"@ericsson.com", false, "who is to be notified via email");
  parameters["reportTelnum"] = ParameterData("0", false, "where to send the SMS notification");

  stringstream ss;
  ss << "TITAN " << this->name_ << ' ' << this->major_version_ << '.' << this->minor_version_;
  user_agent = ss.str();

  this->testcase_count_ = 0;
}

TSTLogger::~TSTLogger()
{
  Free(this->name_);
  Free(this->help_);
  this->name_ = this->help_ = NULL;
}

bool TSTLogger::log_plugin_debug()
{
  return parameters["log_plugin_debug"].get_value()!="0";
}

void TSTLogger::init(const char */*options*/)
{
  cout << "Initializing `" << this->name_ << "' (v" << this->major_version_ << "." << this->minor_version_ << "): " << this->help_ << endl;
  this->is_configured_ = true;
}

void TSTLogger::fini()
{
  if (is_main_proc()) {
    TitanLoggerApi::TimestampType timestamp;
    struct timeval tm;
    gettimeofday(&tm, NULL);
    timestamp.seconds().set_long_long_val((long long int)tm.tv_sec);
    timestamp.microSeconds().set_long_long_val((long long int)tm.tv_usec);
    log_testsuite_stop(timestamp); // TODO: call this from log()
  }
  this->is_configured_ = false;
}

void TSTLogger::set_parameter(const char *parameter_name, const char *parameter_value)
{
  map<string,ParameterData>::iterator it = parameters.find(parameter_name);
  if (it!=parameters.end()) {
    it->second.set_value(parameter_value);
  } else {
    cerr << this->name_ << ": " << "Unsupported parameter: `" << parameter_name << "' with value: `"
         << parameter_value << "'" << endl;
  }
}

void TSTLogger::add_database_params(std::map<std::string,std::string>& req_params)
{
  req_params["dbsUrl"] = parameters["dbsUrl"].get_value();
  req_params["dbUser"] = parameters["dbUser"].get_value();
  req_params["dbPass"] = parameters["dbPass"].get_value();
  req_params["dbName"] = parameters["dbName"].get_value();
}

string TSTLogger::post_message(std::map<std::string,std::string> req_params, const string& TST_service_uri)
{
  add_database_params(req_params);
  try {
    HTTPClient client;
    client.open_connection(parameters["tst_host_name"].get_value(), parameters["tst_service_name"].get_value());
    string response = client.post_request(parameters["tst_host_name"].get_value(), TST_service_uri, user_agent, req_params);
    client.close_connection();
    return response;
  }
  catch (SocketException exc) {
    cerr << this->name_ << ": " << "HTTP error: " << exc.getMessage() << " (" << exc.getReason() << ")\n";
  }
  return "";
}

// most of the message types should be sent only from one main process (MTC in parallel mode)
bool TSTLogger::is_main_proc() const
{
  return TTCN_Runtime::is_mtc() || TTCN_Runtime::is_single();
}

void TSTLogger::log(const TitanLoggerApi::TitanLogEvent& event, bool log_buffered)
{
  log(event, log_buffered, false, false);
}

void TSTLogger::log(const TitanLoggerApi::TitanLogEvent& event,
  bool /*log_buffered*/, bool /*separate_file*/, bool /*use_emergency_mask*/)
{
  const TitanLoggerApi::LogEventType_choice& choice = event.logEvent().choice();
  switch (choice.get_selection()) {
  case TitanLoggerApi::LogEventType_choice::ALT_testcaseOp: {
    const TitanLoggerApi::TestcaseEvent_choice& tec = choice.testcaseOp().choice();
    switch (tec.get_selection()) {
    case TitanLoggerApi::TestcaseEvent_choice::ALT_testcaseStarted:
      if (is_main_proc()) {
        log_testcase_start(tec.testcaseStarted(), event.timestamp());
      }
      break;
    case TitanLoggerApi::TestcaseEvent_choice::ALT_testcaseFinished:
      if (is_main_proc()) {
        log_testcase_stop(tec.testcaseFinished(), event.timestamp());
      }
      break;
    default:
      break;
    }
    break; }
  case TitanLoggerApi::LogEventType_choice::ALT_verdictOp:
    // allow these messages from PTCs
    log_verdictop_reason(choice.verdictOp());
    break;
  default:
    break;
  }
}

void TSTLogger::log_testcase_start(const TitanLoggerApi::QualifiedName& testcaseStarted, const TitanLoggerApi::TimestampType& timestamp)
{
  if (this->testcase_count_ == 0) {
    log_testsuite_start(timestamp); // TODO: call this from log()
  }
  ++this->testcase_count_;

  map<string,string> req_params;
  req_params["suiteId"] = this->suite_id_;
  req_params["tcId"] = (const char *)testcaseStarted.testcase__name();
  req_params["tcHeader"] = req_params["tcId"];
  req_params["tcStartTime"] = get_tst_time_str(timestamp);
  req_params["tcState"] = "0";
  //req_params["tcHtml"] = "";
  req_params["tcClass"] = (const char *)testcaseStarted.module__name();
  req_params["tcMethod"] = req_params["tcId"];

  string resp = post_message(req_params, parameters["tst_tcstart_url"].get_value());

  if ((resp.find("done") != string::npos) && (resp.find("tcaseId") != string::npos)) {
    this->tcase_id_ = resp.substr(resp.find("=") + 1);
    if (log_plugin_debug()) {
      cout << this->name_ << ": " << "Operation `log_testcase_start' successful, returned tcaseId=" << this->tcase_id_ << endl;
    }    
  } else {
    cerr << this->name_ << ": " << "Operation `log_testcase_start' failed: " << resp << endl;
    // Add better error handling.
    return;
  }
}

void TSTLogger::log_testcase_stop(const TitanLoggerApi::TestcaseType& testcaseFinished, const TitanLoggerApi::TimestampType& timestamp)
{
  string tc_state;
  switch (testcaseFinished.verdict()) {
  case TitanLoggerApi::Verdict::v0none: // start (?)
    tc_state = "0";
    break;
  case TitanLoggerApi::Verdict::v1pass: // pass
    tc_state = "1";
    break;
  case TitanLoggerApi::Verdict::v2inconc: // inconclusive
    tc_state = "7";
    break;
  case TitanLoggerApi::Verdict::v3fail: // fail
    tc_state = "2";
    break;
  case TitanLoggerApi::Verdict::v4error: // error
    tc_state = "3";
    break;
  default:
    tc_state = "0";
  }
  map<string,string> req_params;
  req_params["tcaseId"] = this->tcase_id_;
  req_params["tcEndTime"] = get_tst_time_str(timestamp);
  req_params["tcState"] = tc_state;
  req_params["tcUndefined"] = "false"; //?
  req_params["tcAssertion"] = "false"; //?
  req_params["tcTrafficLoss"] = "false"; //?

  string resp = post_message(req_params, parameters["tst_tcstop_url"].get_value());

  if (!resp.compare("done")) {
    if (log_plugin_debug()) {
      cout << this->name_ << ": " << "Operation `log_testcase_stop' successful" << endl;
    }
  } else {
    cerr << this->name_ << ": " << "Operation `log_testcase_stop' failed: " << resp << endl;
    return;
  }
}

void TSTLogger::log_testsuite_start(const TitanLoggerApi::TimestampType& timestamp)
{
  map<string,string> req_params;
  req_params["fwName"] = "TITAN";
  stringstream titanver_ss;
  titanver_ss << TTCN3_MAJOR << '.' << TTCN3_MINOR << ".pl" << TTCN3_PATCHLEVEL;
  req_params["fwVersion"] = titanver_ss.str();
  req_params["suiteStartTime"] = get_tst_time_str(timestamp);
  req_params["testConfigName"] = parameters["testConfigName"].get_value();
  req_params["suiteName"] = parameters["suiteName"].get_value();
  req_params["executingHost"] = parameters["executingHost"].get_value();
  req_params["sutId"] = parameters["sutId"].get_value();
  req_params["sutName"] = parameters["sutName"].get_value();
  req_params["lsvMajor"] = parameters["lsvMajor"].get_value();
  req_params["lsvMinor"] = parameters["lsvMinor"].get_value();
  req_params["runByUser"] = parameters["runByUser"].get_value();
  req_params["projectName"] = parameters["projectName"].get_value();
  req_params["productName"] = parameters["productName"].get_value();
  req_params["productVersion"] = parameters["productVersion"].get_value();
  req_params["notRun"] = "1"; // FIXME?
  req_params["configType"] = parameters["configType"].get_value();
  req_params["configVersion"] = parameters["configVersion"].get_value();
  req_params["testType"] = parameters["testType"].get_value();
  req_params["logLink"] = parameters["logLink"].get_value();
  req_params["logEnd"] = parameters["logEnd"].get_value();
  req_params["reportEmail"] = parameters["reportEmail"].get_value();
  req_params["reportTelnum"] = parameters["reportTelnum"].get_value();

  string resp = post_message(req_params, parameters["tst_tsstart_url"].get_value());

  if ((resp.find("done") != string::npos) && (resp.find("suiteId") != string::npos)) {
    this->suite_id_ = resp.substr(resp.find("=") + 1);
    if (log_plugin_debug()) {
      cout << this->name_ << ": " << "Operation `log_testsuite_start' successful, returned suiteId=" << this->suite_id_ << endl;    
    }
  } else {
    cerr << this->name_ << ": " << "Operation `log_testsuite_start' failed: " << resp << endl;
    return;
  }
}

void TSTLogger::log_testsuite_stop(const TitanLoggerApi::TimestampType& timestamp)
{
  map<string,string> req_params;
  req_params["suiteId"] = this->suite_id_;
  req_params["tsEndTime"] = get_tst_time_str(timestamp);
  req_params["reportEmail"] = parameters["reportEmail"].get_value();
  req_params["reportTelnum"] = parameters["reportTelnum"].get_value();

  string resp = post_message(req_params, parameters["tst_tsstop_url"].get_value());

  if (!resp.compare("done")) {
    if (log_plugin_debug()) {
      cout << this->name_ << ": " << "Operation `log_testsuite_stop' successful" << endl;
    }
  } else {
    cerr << this->name_ << ": " << "Operation `log_testsuite_stop' failed: " << resp << endl;
  }
}

void TSTLogger::log_verdictop_reason(const TitanLoggerApi::VerdictOp& verdictOp)
{
  if (verdictOp.choice().get_selection() == TitanLoggerApi::VerdictOp_choice::ALT_setVerdict) {
    TitanLoggerApi::SetVerdictType setVerdict = verdictOp.choice().setVerdict();
    if (setVerdict.newReason().ispresent() && setVerdict.newReason()().lengthof()>0) {
      map<string,string> req_params;
      req_params["tcaseId"] = this->tcase_id_;
      req_params["tcFailType"] = "0"; //?
      req_params["tcFailNum"] = "1";
      req_params["tcFailReason"] = (const char *)setVerdict.newReason()();
      string resp = post_message(req_params, parameters["tst_tcfailreason_url"].get_value());
      if (!resp.compare("done")) {
        if (log_plugin_debug()) {
          cout << this->name_ << ": " << "Operation log_verdictop_reason' successful" << endl;
        }
      } else {
        cerr << this->name_ << ": " << "Operation log_verdictop_reason' failed: " << resp << endl;
      }
    }
  }
}