ground/gcs/src/libs/utils/logfile.cpp

   1 /**
   2  ******************************************************************************
   3  *
   4  * @file       logfile.cpp
   5  * @author     The LibrePilot Project, http://www.librepilot.org Copyright (C) 2017-2018.
   6  *             The OpenPilot Team, http://www.openpilot.org Copyright (C) 2010.
   7  * @see        The GNU Public License (GPL) Version 3
   8  *
   9  *****************************************************************************/
  10 /*
  11  * This program is free software; you can redistribute it and/or modify
  12  * it under the terms of the GNU General Public License as published by
  13  * the Free Software Foundation; either version 3 of the License, or
  14  * (at your option) any later version.
  15  *
  16  * This program is distributed in the hope that it will be useful, but
  17  * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
  18  * or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
  19  * for more details.
  20  *
  21  * You should have received a copy of the GNU General Public License along
  22  * with this program; if not, write to the Free Software Foundation, Inc.,
  23  * 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
  24  */
  25 #include "logfile.h"
  26
  27 #include <QDebug>
  28 #include <QtGlobal>
  29 #include <QDataStream>
  30
  31 #define TIMESTAMP_SIZE_BYTES 4
  32
  33 LogFile::LogFile(QObject *parent) : QIODevice(parent),
  34     m_timer(this),
  35     m_previousTimeStamp(0),
  36     m_nextTimeStamp(0),
  37     m_lastPlayed(0),
  38     m_timeOffset(0),
  39     m_playbackSpeed(1.0),
  40     m_replayState(STOPPED),
  41     m_useProvidedTimeStamp(false),
  42     m_providedTimeStamp(0),
  43     m_beginTimeStamp(0),
  44     m_endTimeStamp(0),
  45     m_timerTick(0)
  46 {
  47     connect(&m_timer, &QTimer::timeout, this, &LogFile::timerFired);
  48 }
  49
  50 bool LogFile::isSequential() const
  51 {
  52     // returning true fixes "UAVTalk - error : bad type" errors when replaying a log file
  53     return true;
  54 }
  55
  56 /**
  57  * Opens the logfile QIODevice and the underlying logfile. In case
  58  * we want to save the logfile, we open in WriteOnly. In case we
  59  * want to read the logfile, we open in ReadOnly.
  60  */
  61 bool LogFile::open(OpenMode mode)
  62 {
  63     // start a timer for playback
  64     m_myTime.restart();
  65     if (m_file.isOpen()) {
  66         // We end up here when doing a replay, because the connection
  67         // manager will also try to open the QIODevice, even though we just
  68         // opened it after selecting the file, which happens before the
  69         // connection manager call...
  70         return true;
  71     }
  72     qDebug() << "LogFile - open" << fileName();
  73
  74     if (m_file.open(mode) == false) {
  75         qWarning() << "Unable to open " << m_file.fileName() << " for logging";
  76         return false;
  77     }
  78
  79     // TODO: Write a header at the beginng describing objects so that in future
  80     // they can be read back if ID's change
  81
  82     // Must call parent function for QIODevice to pass calls to writeData
  83     // We always open ReadWrite, because otherwise we will get tons of warnings
  84     // during a logfile replay. Read nature is checked upon write ops below.
  85     QIODevice::open(QIODevice::ReadWrite);
  86
  87     return true;
  88 }
  89
  90 void LogFile::close()
  91 {
  92     qDebug() << "LogFile - close" << fileName();
  93     emit aboutToClose();
  94     m_file.close();
  95     QIODevice::close();
  96 }
  97
  98 qint64 LogFile::writeData(const char *data, qint64 dataSize)
  99 {
 100     if (!m_file.isWritable()) {
 101         return dataSize;
 102     }
 103
 104     // If needed, use provided timestamp instead of the GCS timer
 105     // This is used when saving logs from on-board logging
 106     quint32 timeStamp = m_useProvidedTimeStamp ? m_providedTimeStamp : m_myTime.elapsed();
 107
 108     m_file.write((char *)&timeStamp, sizeof(timeStamp));
 109     m_file.write((char *)&dataSize, sizeof(dataSize));
 110
 111     qint64 written = m_file.write(data, dataSize);
 112
 113     // flush (needed to avoid UAVTalk device full errors)
 114     m_file.flush();
 115
 116     if (written != -1) {
 117         emit bytesWritten(written);
 118     }
 119
 120     return dataSize;
 121 }
 122
 123 qint64 LogFile::readData(char *data, qint64 maxlen)
 124 {
 125     QMutexLocker locker(&m_mutex);
 126
 127     qint64 len = qMin(maxlen, (qint64)m_dataBuffer.size());
 128
 129     if (len) {
 130         memcpy(data, m_dataBuffer.data(), len);
 131         m_dataBuffer.remove(0, len);
 132     }
 133
 134     return len;
 135 }
 136
 137 qint64 LogFile::bytesAvailable() const
 138 {
 139     QMutexLocker locker(&m_mutex);
 140
 141     qint64 len = m_dataBuffer.size();
 142
 143     return len;
 144 }
 145
 146 /**
 147     timerFired()
 148
 149     This function is called at a 10 ms interval to fill the replay buffers.
 150
 151  */
 152 void LogFile::timerFired()
 153 {
 154     if (m_replayState != PLAYING) {
 155         return;
 156     }
 157     m_timerTick++;
 158
 159     if (m_file.bytesAvailable() > TIMESTAMP_SIZE_BYTES) {
 160         int time;
 161         time = m_myTime.elapsed();
 162
 163         /*
 164             This code generates an advancing playback window. All samples that fit the window
 165             are replayed. The window is about the size of the timer interval: 10 ms.
 166
 167             Description of used variables:
 168
 169             time              : real-time interval since start of playback (in ms) - now()
 170             m_timeOffset      : real-time interval since start of playback (in ms) - when timerFired() was previously run
 171             m_nextTimeStamp   : read log until this log timestamp has been reached (in ms)
 172             m_lastPlayed      : log referenced timestamp advanced to during previous cycle (in ms)
 173             m_playbackSpeed   : 0.1 .. 1.0 .. 10 replay speedup factor
 174
 175          */
 176
 177         while (m_nextTimeStamp < (m_lastPlayed + (double)(time - m_timeOffset) * m_playbackSpeed)) {
 178             // advance the replay window for the next time period
 179             m_lastPlayed += ((double)(time - m_timeOffset) * m_playbackSpeed);
 180
 181             // read data size
 182             qint64 dataSize;
 183             if (m_file.bytesAvailable() < (qint64)sizeof(dataSize)) {
 184                 qDebug() << "LogFile replay - end of log file reached";
 185                 resetReplay();
 186                 return;
 187             }
 188             m_file.read((char *)&dataSize, sizeof(dataSize));
 189
 190             // check size consistency
 191             if (dataSize < 1 || dataSize > (1024 * 1024)) {
 192                 qWarning() << "LogFile replay - corrupted log file! Unlikely packet size:" << dataSize;
 193                 stopReplay();
 194                 return;
 195             }
 196
 197             // read data
 198             if (m_file.bytesAvailable() < dataSize) {
 199                 qDebug() << "LogFile replay - end of log file reached";
 200                 resetReplay();
 201                 return;
 202             }
 203             QByteArray data = m_file.read(dataSize);
 204
 205             // make data available
 206             m_mutex.lock();
 207             m_dataBuffer.append(data);
 208             m_mutex.unlock();
 209
 210             emit readyRead();
 211
 212             // rate-limit slider bar position updates to 10 updates per second
 213             if (m_timerTick % 10 == 0) {
 214                 emit playbackPositionChanged(m_nextTimeStamp);
 215             }
 216             // read next timestamp
 217             if (m_file.bytesAvailable() < (qint64)sizeof(m_nextTimeStamp)) {
 218                 qDebug() << "LogFile replay - end of log file reached";
 219                 resetReplay();
 220                 return;
 221             }
 222             m_previousTimeStamp = m_nextTimeStamp;
 223             m_file.read((char *)&m_nextTimeStamp, sizeof(m_nextTimeStamp));
 224
 225             // some validity checks
 226             if ((m_nextTimeStamp < m_previousTimeStamp) // logfile goes back in time
 227                 || ((m_nextTimeStamp - m_previousTimeStamp) > 60 * 60 * 1000)) { // gap of more than 60 minutes
 228                 qWarning() << "LogFile replay - corrupted log file! Unlikely timestamp:" << m_nextTimeStamp << "after" << m_previousTimeStamp;
 229                 stopReplay();
 230                 return;
 231             }
 232
 233             m_timeOffset = time;
 234             time = m_myTime.elapsed(); // number of milliseconds since start of playback
 235         }
 236     } else {
 237         qDebug() << "LogFile replay - end of log file reached";
 238         resetReplay();
 239     }
 240 }
 241
 242 bool LogFile::isPlaying() const
 243 {
 244     return m_file.isOpen() && m_timer.isActive();
 245 }
 246
 247 /**
 248  * FUNCTION: startReplay()
 249  *
 250  * Starts replaying a newly opened logfile.
 251  * Starts a timer: m_timer
 252  *
 253  * This function and the stopReplay() function should only ever be called from the same thread.
 254  * This is required for correct control of the timer.
 255  *
 256  */
 257 bool LogFile::startReplay()
 258 {
 259     // Walk through logfile and create timestamp index
 260     // Don't start replay if there was a problem indexing the logfile.
 261     if (!buildIndex()) {
 262         return false;
 263     }
 264
 265     m_timerTick = 0;
 266
 267     if (!m_file.isOpen() || m_timer.isActive()) {
 268         return false;
 269     }
 270     qDebug() << "LogFile - startReplay";
 271
 272     m_myTime.restart();
 273     m_timeOffset        = 0;
 274     m_lastPlayed        = 0;
 275     m_previousTimeStamp = 0;
 276     m_nextTimeStamp     = 0;
 277     m_mutex.lock();
 278     m_dataBuffer.clear();
 279     m_mutex.unlock();
 280
 281     // read next timestamp
 282     if (m_file.bytesAvailable() < (qint64)sizeof(m_nextTimeStamp)) {
 283         qWarning() << "LogFile - invalid log file!";
 284         return false;
 285     }
 286     m_file.read((char *)&m_nextTimeStamp, sizeof(m_nextTimeStamp));
 287
 288     m_timer.setInterval(10);
 289     m_timer.start();
 290     m_replayState = PLAYING;
 291
 292     emit replayStarted();
 293     return true;
 294 }
 295
 296 /**
 297  * FUNCTION: stopReplay()
 298  *
 299  * Stops replaying the logfile.
 300  * Stops the timer: m_timer
 301  *
 302  * This function and the startReplay() function should only ever be called from the same thread.
 303  * This is a requirement to be able to control the timer.
 304  *
 305  */
 306 bool LogFile::stopReplay()
 307 {
 308     if (!m_file.isOpen()) {
 309         return false;
 310     }
 311     if (m_timer.isActive()) {
 312         m_timer.stop();
 313     }
 314
 315     qDebug() << "LogFile - stopReplay";
 316     m_replayState = STOPPED;
 317
 318     emit replayFinished();
 319     return true;
 320 }
 321
 322 /**
 323  * FUNCTION: resetReplay()
 324  *
 325  * Stops replaying the logfile.
 326  * Stops the timer: m_timer
 327  * Resets playback position to the start of the logfile
 328  * through the emission of a replayCompleted signal.
 329  *
 330  */
 331 bool LogFile::resetReplay()
 332 {
 333     if (!m_file.isOpen()) {
 334         return false;
 335     }
 336     if (m_timer.isActive()) {
 337         m_timer.stop();
 338     }
 339
 340     qDebug() << "LogFile - resetReplay";
 341     m_replayState = STOPPED;
 342
 343     emit replayCompleted();
 344     return true;
 345 }
 346
 347 /**
 348  * SLOT: resumeReplay()
 349  *
 350  * Resumes replay from the given position.
 351  * If no position is given, resumes from the last position
 352  *
 353  */
 354 bool LogFile::resumeReplay(quint32 desiredPosition)
 355 {
 356     if (m_timer.isActive()) {
 357         return false;
 358     }
 359     qDebug() << "LogFile - resumeReplay";
 360
 361     // Clear the playout buffer:
 362     m_mutex.lock();
 363     m_dataBuffer.clear();
 364     m_mutex.unlock();
 365
 366     m_file.seek(0);
 367
 368     /* Skip through the logfile until we reach the desired position.
 369        Looking for the next log timestamp after the desired position
 370        has the advantage that it skips over parts of the log
 371        where data might be missing.
 372      */
 373     for (int i = 0; i < m_timeStamps.size(); i++) {
 374         if (m_timeStamps.at(i) >= desiredPosition) {
 375             int bytesToSkip = m_timeStampPositions.at(i);
 376             bool seek_ok    = m_file.seek(bytesToSkip);
 377             if (!seek_ok) {
 378                 qWarning() << "LogFile resumeReplay - an error occurred while seeking through the logfile.";
 379             }
 380             m_lastPlayed = m_timeStamps.at(i);
 381             break;
 382         }
 383     }
 384     m_file.read((char *)&m_nextTimeStamp, sizeof(m_nextTimeStamp));
 385
 386     // Real-time timestamps don't not need to match the log timestamps.
 387     // However the delta between real-time variables "m_timeOffset" and "m_myTime" is important.
 388     // This delta determines the number of log entries replayed per cycle.
 389
 390     // Set the real-time interval to 0 to start with:
 391     m_myTime.restart();
 392     m_timeOffset  = 0;
 393
 394     m_replayState = PLAYING;
 395
 396     m_timer.start();
 397
 398     // Notify UI that playback has resumed
 399     emit replayStarted();
 400     return true;
 401 }
 402
 403 /**
 404  * SLOT: pauseReplay()
 405  *
 406  * Pauses replay while storing the current playback position
 407  *
 408  */
 409 bool LogFile::pauseReplay()
 410 {
 411     if (!m_timer.isActive()) {
 412         return false;
 413     }
 414     qDebug() << "LogFile - pauseReplay";
 415     m_timer.stop();
 416     m_replayState = PAUSED;
 417     return true;
 418 }
 419
 420 /**
 421  * SLOT: pauseReplayAndResetPosition()
 422  *
 423  * Pauses replay and resets the playback position to the start of the logfile
 424  *
 425  */
 426 bool LogFile::pauseReplayAndResetPosition()
 427 {
 428     if (!m_file.isOpen() || !m_timer.isActive()) {
 429         return false;
 430     }
 431     qDebug() << "LogFile - pauseReplayAndResetPosition";
 432     m_timer.stop();
 433     m_replayState       = STOPPED;
 434
 435     m_timeOffset        = 0;
 436     m_lastPlayed        = m_timeStamps.at(0);
 437     m_previousTimeStamp = 0;
 438     m_nextTimeStamp     = 0;
 439
 440     return true;
 441 }
 442
 443 /**
 444  * FUNCTION: getReplayState()
 445  *
 446  * Returns the current replay status.
 447  *
 448  */
 449 ReplayState LogFile::getReplayState()
 450 {
 451     return m_replayState;
 452 }
 453
 454 /**
 455  * FUNCTION: buildIndex()
 456  *
 457  * Walk through the opened logfile and stores the first and last position timestamps.
 458  * Also builds an index for quickly skipping to a specific position in the logfile.
 459  *
 460  * Returns true when indexing has completed successfully.
 461  * Returns false when a problem was encountered.
 462  *
 463  */
 464 bool LogFile::buildIndex()
 465 {
 466     quint32 timeStamp;
 467     qint64 totalSize;
 468     qint64 readPointer = 0;
 469     quint64 index = 0;
 470     int bytesRead = 0;
 471
 472     qDebug() << "LogFile - buildIndex";
 473
 474     // Ensure empty vectors:
 475     m_timeStampPositions.clear();
 476     m_timeStamps.clear();
 477
 478     QByteArray arr = m_file.readAll();
 479     totalSize = arr.size();
 480     QDataStream dataStream(&arr, QIODevice::ReadOnly);
 481
 482     // set the first timestamp
 483     if (totalSize - readPointer >= TIMESTAMP_SIZE_BYTES) {
 484         bytesRead = dataStream.readRawData((char *)&timeStamp, TIMESTAMP_SIZE_BYTES);
 485         if (bytesRead != TIMESTAMP_SIZE_BYTES) {
 486             qWarning() << "LogFile buildIndex - read first timeStamp: readRawData returned unexpected number of bytes:" << bytesRead << "at position" << readPointer << "\n";
 487             return false;
 488         }
 489         m_timeStamps.append(timeStamp);
 490         m_timeStampPositions.append(readPointer);
 491         readPointer     += TIMESTAMP_SIZE_BYTES;
 492         index++;
 493         m_beginTimeStamp = timeStamp;
 494         m_endTimeStamp   = timeStamp;
 495     }
 496
 497     while (true) {
 498         qint64 dataSize;
 499
 500         // Check if there are enough bytes remaining for a correct "dataSize" field
 501         if (totalSize - readPointer < (qint64)sizeof(dataSize)) {
 502             qWarning() << "LogFile buildIndex - logfile corrupted! Unexpected end of file";
 503             return false;
 504         }
 505
 506         // Read the dataSize field and check for I/O errors
 507         bytesRead = dataStream.readRawData((char *)&dataSize, sizeof(dataSize));
 508         if (bytesRead != sizeof(dataSize)) {
 509             qWarning() << "LogFile buildIndex - read dataSize: readRawData returned unexpected number of bytes:" << bytesRead << "at position" << readPointer << "\n";
 510             return false;
 511         }
 512
 513         readPointer += sizeof(dataSize);
 514
 515         if (dataSize < 1 || dataSize > (1024 * 1024)) {
 516             qWarning() << "LogFile buildIndex - logfile corrupted! Unlikely packet size: " << dataSize << "\n";
 517             return false;
 518         }
 519
 520         // Check if there are enough bytes remaining
 521         if (totalSize - readPointer < dataSize) {
 522             qWarning() << "LogFile buildIndex - logfile corrupted! Unexpected end of file";
 523             return false;
 524         }
 525
 526         // skip reading the data (we don't need it at this point)
 527         readPointer += dataStream.skipRawData(dataSize);
 528
 529         // read the next timestamp
 530         if (totalSize - readPointer >= TIMESTAMP_SIZE_BYTES) {
 531             bytesRead = dataStream.readRawData((char *)&timeStamp, TIMESTAMP_SIZE_BYTES);
 532             if (bytesRead != TIMESTAMP_SIZE_BYTES) {
 533                 qWarning() << "LogFile buildIndex - read timeStamp, readRawData returned unexpected number of bytes:" << bytesRead << "at position" << readPointer << "\n";
 534                 return false;
 535             }
 536
 537             // some validity checks
 538             if (timeStamp < m_endTimeStamp // logfile goes back in time
 539                 || (timeStamp - m_endTimeStamp) > (60 * 60 * 1000)) { // gap of more than 60 minutes)
 540                 qWarning() << "LogFile buildIndex - logfile corrupted! Unlikely timestamp " << timeStamp << " after " << m_endTimeStamp;
 541                 return false;
 542             }
 543
 544             m_timeStamps.append(timeStamp);
 545             m_timeStampPositions.append(readPointer);
 546             readPointer   += TIMESTAMP_SIZE_BYTES;
 547             index++;
 548             m_endTimeStamp = timeStamp;
 549         } else {
 550             // Break without error (we expect to end at this location when we are at the end of the logfile)
 551             break;
 552         }
 553     }
 554
 555     emit timesChanged(m_beginTimeStamp, m_endTimeStamp);
 556
 557     // reset the read pointer to the start of the file
 558     m_file.seek(0);
 559
 560     return true;
 561 }