Deadline using ELPP_THREAD_SAFE

[adamfowleruk]

On both 9.80 and 9.83 if using thread safety with the below minimal example (uses Microsoft's cpprest aka casablanca library, from GitHub), after a few iterations there will be a thread deadlock. There is no way around this. I need this working for a project. If I cannot get thread safety to work I'll have to migrate to another logging library, but I really don't want to do that!

All help much appreciated. I'm testing on a Mac using clang.

/*
#ifndef ELPP_STACKTRACE_ON_CRASH
#define ELPP_STACKTRACE_ON_CRASH 1
#endif
*/

#ifndef ELPP_THREAD_SAFE
#define ELPP_THREAD_SAFE 1
#endif

/*
#ifndef ELPP_FORCE_USE_STD_THREAD
#define ELPP_FORCE_USE_STD_THREAD 1
#endif
*/

/*
#ifndef ELPP_EXPERIMENTAL_ASYNC
#define ELPP_EXPERIMENTAL_ASYNC 1
#endif
*/

#include "mlclient/ext/easylogging++.h"

INITIALIZE_EASYLOGGINGPP

#include <cpprest/http_client.h>
#include <array>
#include <iostream>

class ResultsHolder {
public:
  ResultsHolder(el::Logger* logger) : logger(logger), total(-1), lastFetched(0), results() {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    ;
  };

  void setResult(int idx,int value) {
    //TIMED_FUNC(ResultsHolder_setResult);
    results[idx] = value;
  };
  void incrementLastFetched(int by) {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    lastFetched += by;
  };
  int getResult(int idx) {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    return results[idx];
  };
  int getTotal() {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    return total;
  };
  void setTotal(int t) {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    total = t;
  };
  int getLastFetched() {
    //TIMED_FUNC(ResultsHolder_ResultsHolder);
    return lastFetched;
  };
  el::Logger* getLogger() {
    return logger;
  };

private:
  el::Logger* logger;
  int total; // not fetched results yet
  int lastFetched;
  std::array<int,100000> results;
};

int main(int argc, const char * argv[])
{
  std::cout << "In Main Func" << std::endl;
  START_EASYLOGGINGPP(argc, argv);

  el::Configurations defaultConf;
  defaultConf.setToDefault();
  // Values are always std::string
  defaultConf.setGlobally(el::ConfigurationType::Format, "%datetime %level %fbase:%line %msg");
  //defaultConf.setGlobally(el::ConfigurationType::ToStandardOutput, "false");
  // default logger uses default configurations
  el::Loggers::reconfigureLogger("default", defaultConf);

  el::Configurations performanceConf;
  performanceConf.setToDefault();
  performanceConf.set(el::Level::Info, el::ConfigurationType::Format, "%msg");
  performanceConf.set(el::Level::Info,el::ConfigurationType::Filename,"../performance.log"); /// TODO make output file include version number of this upcoming release
  //performanceConf.set(el::Level::Info,el::ConfigurationType::MillisecondsWidth,"6");
  el::Loggers::reconfigureLogger("performance", performanceConf);
  el::Loggers::addFlag(el::LoggingFlag::FixedTimeFormat); // ensures performance numbers are always quoted as seconds, never formatted

  el::Logger* logger = el::Loggers::getLogger("default");

  std::cout << "Running producer..." << std::endl;

  ResultsHolder rh(logger);

  std::cout << "Creating initial results task" << std::endl;
  pplx::task<void> runningTask([&rh] () {
    /*
    for (int j = 0;j < 100000000;j++) {
      float k = j * 47 / 0.33;
    }
    */
    for (int i3 = 0;i3 <= 9;i3++) {
      //rh.getLogger()->debug("initial populating: %v" , i3);
      rh.setResult(i3,i3 * i3);
    }
    rh.incrementLastFetched(9);
    rh.setTotal(100000);
  });

  if (-1 == rh.getTotal()) {
    logger->debug("Waiting for initial population");
    std::cout << "No results fetched yet. Waiting for initial results task." << std::endl;
    runningTask.wait();
  }

  for (int i = 0;i < rh.getTotal();i++) {
    if (i > rh.getLastFetched()) {
      logger->debug("Waiting for result last page runningTask");
      std::cout << "Waiting for result: " << i << std::endl;
      runningTask.wait();
    }
    //std::cout << "Result at index: " << i << " is: " << rh.getResult(i) << std::endl;
    logger->debug("Result at index: %v is: %v" , i , rh.getResult(i));
    // now check to see if we need to continue the task
    if (runningTask.is_done() && i > rh.getLastFetched() - 10) {
      //std::cout << "Scheduling the next fetch task (fire and forget)" << std::endl;
      runningTask = pplx::task<void>([&rh] () {
        /*
        for (int j = 0;j < 100000000;j++) {
          float k = j * 47 / 0.33;
        }
         */
        for (int i2 = rh.getLastFetched() + 1;i2 <= rh.getLastFetched() + 10;i2++) {
          rh.getLogger()->debug("second task populating: %v" , i2);
          rh.setResult(i2,i2 * i2);
        }
        rh.incrementLastFetched(10);
        //std::cout << "Just finished fetching results up to: " << rh.getLastFetched() << std::endl;
      });
    }

    // now add our own thread delay, increasing as we process more of the result set (so we see both sides of the performance curve)
    // At start of test - we see main thread wait for initial results
    // Toward start of test - we see main thread wait for second page
    // Toward end of test - we see fetching thread keeps almost 2 pages ahead of processing thread

    /*
    for (int j = 0;j < 1000000 * i ;j++) {
      float k = j * 47 / 0.33;
    }
    */
  }

  std::cout << "Completing main thread" << std::endl;

  return 0;
}

[adamfowleruk]

PS If you comment out this line:-

rh.getLogger()->debug("second task populating: %v" , i2);

It works fine. The issue only shows up when you are logging in both threads.