LogReplayLink.cc 19.1 KB
Newer Older
1 2 3 4 5 6 7 8
/****************************************************************************
 *
 *   (c) 2009-2016 QGROUNDCONTROL PROJECT <http://www.qgroundcontrol.org>
 *
 * QGroundControl is licensed according to the terms in the file
 * COPYING.md in the root of the source code directory.
 *
 ****************************************************************************/
Don Gagne's avatar
Don Gagne committed
9 10 11 12


#include "LogReplayLink.h"
#include "LinkManager.h"
13
#include "QGCApplication.h"
Don Gagne's avatar
Don Gagne committed
14 15

#include <QFileInfo>
DonLakeFlyer's avatar
DonLakeFlyer committed
16
#include <QtEndian>
Don Gagne's avatar
Don Gagne committed
17 18 19

const char*  LogReplayLinkConfiguration::_logFilenameKey = "logFilename";

20 21
LogReplayLinkConfiguration::LogReplayLinkConfiguration(const QString& name)
	: LinkConfiguration(name)
Don Gagne's avatar
Don Gagne committed
22 23 24 25
{
    
}

26 27
LogReplayLinkConfiguration::LogReplayLinkConfiguration(LogReplayLinkConfiguration* copy)
	: LinkConfiguration(copy)
Don Gagne's avatar
Don Gagne committed
28 29 30 31 32 33 34 35
{
    _logFilename = copy->logFilename();
}

void LogReplayLinkConfiguration::copyFrom(LinkConfiguration *source)
{
    LinkConfiguration::copyFrom(source);
    LogReplayLinkConfiguration* ssource = dynamic_cast<LogReplayLinkConfiguration*>(source);
DonLakeFlyer's avatar
DonLakeFlyer committed
36 37 38 39 40
    if (ssource) {
        _logFilename = ssource->logFilename();
    } else {
        qWarning() << "Internal error";
    }
Don Gagne's avatar
Don Gagne committed
41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67
}

void LogReplayLinkConfiguration::saveSettings(QSettings& settings, const QString& root)
{
    settings.beginGroup(root);
    settings.setValue(_logFilenameKey, _logFilename);
    settings.endGroup();
}

void LogReplayLinkConfiguration::loadSettings(QSettings& settings, const QString& root)
{
    settings.beginGroup(root);
    _logFilename = settings.value(_logFilenameKey, "").toString();
    settings.endGroup();
}

void LogReplayLinkConfiguration::updateSettings(void)
{
    // Doesn't support changing filename on the fly is already connected
}

QString LogReplayLinkConfiguration::logFilenameShort(void)
{
    QFileInfo fi(_logFilename);
    return fi.fileName();
}

68 69 70 71 72
LogReplayLink::LogReplayLink(SharedLinkConfigurationPointer& config)
    : LinkInterface(config)
    , _logReplayConfig(qobject_cast<LogReplayLinkConfiguration*>(config.data()))
    , _connected(false)
    , _replayAccelerationFactor(1.0f)
Don Gagne's avatar
Don Gagne committed
73
{
DonLakeFlyer's avatar
DonLakeFlyer committed
74 75 76
    if (!_logReplayConfig) {
        qWarning() << "Internal error";
    }
77 78

    _errorTitle = tr("Log Replay Error");
Don Gagne's avatar
Don Gagne committed
79 80 81
    
    _readTickTimer.moveToThread(this);
    
82
    QObject::connect(&_readTickTimer, &QTimer::timeout, this, &LogReplayLink::_readNextLogEntry);
Don Gagne's avatar
Don Gagne committed
83 84 85 86 87 88 89 90 91 92 93 94 95 96 97
    QObject::connect(this, &LogReplayLink::_playOnThread, this, &LogReplayLink::_play);
    QObject::connect(this, &LogReplayLink::_pauseOnThread, this, &LogReplayLink::_pause);
    QObject::connect(this, &LogReplayLink::_setAccelerationFactorOnThread, this, &LogReplayLink::_setAccelerationFactor);
    
    moveToThread(this);
}

LogReplayLink::~LogReplayLink(void)
{
    _disconnect();
}

bool LogReplayLink::_connect(void)
{
    // Disallow replay when any links are connected
98
    if (qgcApp()->toolbox()->multiVehicleManager()->activeVehicle()) {
99
        emit communicationError(_errorTitle, tr("You must close all connections prior to replaying a log."));
Don Gagne's avatar
Don Gagne committed
100 101 102
        return false;
    }

Don Gagne's avatar
Don Gagne committed
103 104 105 106 107 108
    _mavlinkChannel = qgcApp()->toolbox()->linkManager()->_reserveMavlinkChannel();
    if (_mavlinkChannel == 0) {
        qWarning() << "No mavlink channels available";
        return false;
    }

Don Gagne's avatar
Don Gagne committed
109 110 111 112 113 114 115 116
    if (isRunning()) {
        quit();
        wait();
    }
    start(HighPriority);
    return true;
}

Don Gagne's avatar
Don Gagne committed
117
void LogReplayLink::_disconnect(void)
Don Gagne's avatar
Don Gagne committed
118 119 120 121 122
{
    if (_connected) {
        quit();
        wait();
        _connected = false;
Don Gagne's avatar
Don Gagne committed
123 124 125 126 127

        if (_mavlinkChannel != 0) {
            qgcApp()->toolbox()->linkManager()->_freeMavlinkChannel(_mavlinkChannel);
        }

Don Gagne's avatar
Don Gagne committed
128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146
        emit disconnected();
    }
}

void LogReplayLink::run(void)
{
    // Load the log file
    if (!_loadLogFile()) {
        return;
    }
    
    _connected = true;
    emit connected();
    
    // Start playback
    _play();

    // Run normal event loop until exit
    exec();
147 148
    
    _readTickTimer.stop();
Don Gagne's avatar
Don Gagne committed
149 150 151 152 153 154 155 156 157
}

void LogReplayLink::_replayError(const QString& errorMsg)
{
    qDebug() << _errorTitle << errorMsg;
    emit communicationError(_errorTitle, errorMsg);
}

/// Since this is log replay, we just drops writes on the floor
158
void LogReplayLink::_writeBytes(const QByteArray bytes)
Don Gagne's avatar
Don Gagne committed
159 160 161 162 163 164 165 166
{
    Q_UNUSED(bytes);
}

/// Parses a BigEndian quint64 timestamp
/// @return A Unix timestamp in microseconds UTC for found message or 0 if parsing failed
quint64 LogReplayLink::_parseTimestamp(const QByteArray& bytes)
{
DonLakeFlyer's avatar
DonLakeFlyer committed
167
    quint64 timestamp = qFromBigEndian(*((quint64*)(bytes.constData())));
Don Gagne's avatar
Don Gagne committed
168 169 170 171 172
    quint64 currentTimestamp = ((quint64)QDateTime::currentMSecsSinceEpoch()) * 1000;
    
    // Now if the parsed timestamp is in the future, it must be an old file where the timestamp was stored as
    // little endian, so switch it.
    if (timestamp > currentTimestamp) {
DonLakeFlyer's avatar
DonLakeFlyer committed
173
        timestamp = qbswap(timestamp);
Don Gagne's avatar
Don Gagne committed
174 175 176 177 178
    }
    
    return timestamp;
}

Don Gagne's avatar
Don Gagne committed
179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208
/// Reads the next mavlink message from the log
///     @param bytes[output] Bytes for mavlink message
/// @return Unix timestamp in microseconds UTC for NEXT mavlink message or 0 if no message found
quint64 LogReplayLink::_readNextMavlinkMessage(QByteArray& bytes)
{
    char                nextByte;
    mavlink_status_t    status;

    bytes.clear();

    while (_logFile.getChar(&nextByte)) { // Loop over every byte
        mavlink_message_t message;
        bool messageFound = mavlink_parse_char(_mavlinkChannel, nextByte, &message, &status);

        if (status.parse_state == MAVLINK_PARSE_STATE_GOT_STX) {
            // This is the possible beginning of a mavlink message, clear any partial bytes
            bytes.clear();
        }
        bytes.append(nextByte);

        if (messageFound) {
            // Return the timestamp for the next message
            QByteArray rawTime = _logFile.read(cbTimestamp);
            return _parseTimestamp(rawTime);
        }
    }

    return 0;
}

Ricardo de Almeida Gonzaga's avatar
Ricardo de Almeida Gonzaga committed
209
/// Seeks to the beginning of the next successfully parsed mavlink message in the log file.
Don Gagne's avatar
Don Gagne committed
210 211 212 213
///     @param nextMsg[output] Parsed next message that was found
/// @return A Unix timestamp in microseconds UTC for found message or 0 if parsing failed
quint64 LogReplayLink::_seekToNextMavlinkMessage(mavlink_message_t* nextMsg)
{
214 215 216 217
    char                nextByte;
    mavlink_status_t    status;
    qint64              messageStartPos = -1;

Don Gagne's avatar
Don Gagne committed
218
    while (_logFile.getChar(&nextByte)) { // Loop over every byte
Don Gagne's avatar
Don Gagne committed
219
        bool messageFound = mavlink_parse_char(_mavlinkChannel, nextByte, nextMsg, &status);
220 221 222 223 224

        if (status.parse_state == MAVLINK_PARSE_STATE_GOT_STX) {
            // This is the possible beginning of a mavlink message
            messageStartPos = _logFile.pos() - 1;
        }
Don Gagne's avatar
Don Gagne committed
225 226 227
        
        // If we've found a message, jump back to the start of the message, grab the timestamp,
        // and go back to the end of this file.
228 229
        if (messageFound && messageStartPos != -1) {
            _logFile.seek(messageStartPos - cbTimestamp);
Don Gagne's avatar
Don Gagne committed
230 231 232 233 234 235 236 237 238 239 240
            QByteArray rawTime = _logFile.read(cbTimestamp);
            return _parseTimestamp(rawTime);
        }
    }
    
    return 0;
}

bool LogReplayLink::_loadLogFile(void)
{
    QString errorMsg;
241
    QString logFilename = _logReplayConfig->logFilename();
Don Gagne's avatar
Don Gagne committed
242 243 244 245
    QFileInfo logFileInfo;
    int logDurationSecondsTotal;
    
    if (_logFile.isOpen()) {
246
        errorMsg = tr("Attempt to load new log while log being played");
Don Gagne's avatar
Don Gagne committed
247 248 249 250 251
        goto Error;
    }
    
    _logFile.setFileName(logFilename);
    if (!_logFile.open(QFile::ReadOnly)) {
252
        errorMsg = tr("Unable to open log file: '%1', error: %2").arg(logFilename).arg(_logFile.errorString());
Don Gagne's avatar
Don Gagne committed
253 254 255 256 257
        goto Error;
    }
    logFileInfo.setFile(logFilename);
    _logFileSize = logFileInfo.size();
    
258
    _logTimestamped = logFilename.endsWith(".tlog");
Don Gagne's avatar
Don Gagne committed
259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281
    
    if (_logTimestamped) {
        // Get the first timestamp from the log
        // This should be a big-endian uint64.
        QByteArray timestamp = _logFile.read(cbTimestamp);
        quint64 startTimeUSecs = _parseTimestamp(timestamp);
        
        // Now find the last timestamp by scanning for the last MAVLink packet and
        // find the timestamp before it. To do this we start searchin a little before
        // the end of the file, specifically the maximum MAVLink packet size + the
        // timestamp size. This guarantees that we will hit a MAVLink packet before
        // the end of the file. Unfortunately, it basically guarantees that we will
        // hit more than one. This is why we have to search for a bit.
        qint64 fileLoc = _logFile.size() - MAVLINK_MAX_PACKET_LEN - cbTimestamp;
        _logFile.seek(fileLoc);
        quint64 endTimeUSecs = startTimeUSecs; // Set a sane default for the endtime
        mavlink_message_t msg;
        quint64 messageTimeUSecs;
        while ((messageTimeUSecs = _seekToNextMavlinkMessage(&msg)) > endTimeUSecs) {
            endTimeUSecs = messageTimeUSecs;
        }
        
        if (endTimeUSecs == startTimeUSecs) {
282
            errorMsg = tr("The log file '%1' is corrupt. No valid timestamps were found at the end of the file.").arg(logFilename);
Don Gagne's avatar
Don Gagne committed
283 284 285 286 287 288 289 290
            goto Error;
        }
        
        // Remember the start and end time so we can move around this _logFile with the slider.
        _logEndTimeUSecs = endTimeUSecs;
        _logStartTimeUSecs = startTimeUSecs;
        _logDurationUSecs = endTimeUSecs - startTimeUSecs;
        _logCurrentTimeUSecs = startTimeUSecs;
291

Don Gagne's avatar
Don Gagne committed
292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334 335 336 337
        // Reset our log file so when we go to read it for the first time, we start at the beginning.
        _logFile.reset();
        
        logDurationSecondsTotal = (_logDurationUSecs) / 1000000;
    } else {
        // Load in binary mode. In this mode, files should be have a filename postfix
        // of the baud rate they were recorded at, like `test_run_115200.bin`. Then on
        // playback, the datarate is equal to set to this value.
        
        
        // Set baud rate if any present. Otherwise we default to 57600.
        QStringList parts = logFileInfo.baseName().split("_");
        _binaryBaudRate = _defaultBinaryBaudRate;
        if (parts.count() > 1)
        {
            bool ok;
            int rate = parts.last().toInt(&ok);
            // 9600 baud to 100 MBit
            if (ok && (rate > 9600 && rate < 100000000))
            {
                // Accept this as valid baudrate
                _binaryBaudRate = rate;
            }
        }
        
        logDurationSecondsTotal = logFileInfo.size() / (_binaryBaudRate / 10);
    }
    
    emit logFileStats(_logTimestamped, logDurationSecondsTotal, _binaryBaudRate);
    
    return true;
    
Error:
    if (_logFile.isOpen()) {
        _logFile.close();
    }
    _replayError(errorMsg);
    return false;
}

/// This function will read the next available log entry. It will then start
/// the _readTickTimer timer to read the new log entry at the appropriate time.
/// It might not perfectly match the timing of the log file, but it will never
/// induce a static drift into the log file replay.
void LogReplayLink::_readNextLogEntry(void)
{
Don Gagne's avatar
Don Gagne committed
338 339
    QByteArray bytes;

Don Gagne's avatar
Don Gagne committed
340 341 342 343 344 345 346 347 348 349 350
    // If we have a file with timestamps, try and pace this out following the time differences
    // between the timestamps and the current playback speed.
    if (_logTimestamped) {
        // Now parse MAVLink messages, grabbing their timestamps as we go. We stop once we
        // have at least 3ms until the next one.
        
        // We track what the next execution time should be in milliseconds, which we use to set
        // the next timer interrupt.
        int timeToNextExecutionMSecs = 0;
        
        while (timeToNextExecutionMSecs < 3) {
Don Gagne's avatar
Don Gagne committed
351 352 353
            // Read the next mavlink message from the log
            qint64 nextTimeUSecs = _readNextMavlinkMessage(bytes);
            emit bytesReceived(this, bytes);
Don Gagne's avatar
Don Gagne committed
354 355 356 357 358 359 360
            emit playbackPercentCompleteChanged(((float)(_logCurrentTimeUSecs - _logStartTimeUSecs) / (float)_logDurationUSecs) * 100);
            
            if (_logFile.atEnd()) {
                _finishPlayback();
                return;
            }
            
Don Gagne's avatar
Don Gagne committed
361
            _logCurrentTimeUSecs = nextTimeUSecs;
Don Gagne's avatar
Don Gagne committed
362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394
            
            // Calculate how long we should wait in real time until parsing this message.
            // We pace ourselves relative to the start time of playback to fix any drift (initially set in play())
            qint64 timeDiffMSecs = ((_logCurrentTimeUSecs - _logStartTimeUSecs) / 1000) / _replayAccelerationFactor;
            quint64 desiredPacedTimeMSecs = _playbackStartTimeMSecs + timeDiffMSecs;
            quint64 currentTimeMSecs = (quint64)QDateTime::currentMSecsSinceEpoch();
            timeToNextExecutionMSecs = desiredPacedTimeMSecs - currentTimeMSecs;
        }
        
        // And schedule the next execution of this function.
        _readTickTimer.start(timeToNextExecutionMSecs);
    }
    else
    {
        // Binary format - read at fixed rate
        const int len = 100;
        QByteArray chunk = _logFile.read(len);
        
        emit bytesReceived(this, chunk);
        emit playbackPercentCompleteChanged(((float)_logFile.pos() / (float)_logFileSize) * 100);
        
        // Check if reached end of file before reading next timestamp
        if (chunk.length() < len || _logFile.atEnd())
        {
            _finishPlayback();
            return;
        }
    }
    
}

void LogReplayLink::_play(void)
{
395
    qgcApp()->toolbox()->linkManager()->setConnectionsSuspended(tr("Connect not allowed during Flight Data replay."));
Don Gagne's avatar
Don Gagne committed
396
#ifndef __mobile__
397
    qgcApp()->toolbox()->mavlinkProtocol()->suspendLogForReplay(true);
Don Gagne's avatar
Don Gagne committed
398
#endif
Don Gagne's avatar
Don Gagne committed
399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426
    
    // Make sure we aren't at the end of the file, if we are, reset to the beginning and play from there.
    if (_logFile.atEnd()) {
        _resetPlaybackToBeginning();
    }
    
    // Always correct the current start time such that the next message will play immediately at playback.
    // We do this by subtracting the current file playback offset  from now()
    _playbackStartTimeMSecs = (quint64)QDateTime::currentMSecsSinceEpoch() - ((_logCurrentTimeUSecs - _logStartTimeUSecs) / 1000);
    
    // Start timer
    if (_logTimestamped) {
        _readTickTimer.start(1);
    } else {
        // Read len bytes at a time
        int len = 100;
        // Calculate the number of times to read 100 bytes per second
        // to guarantee the baud rate, then divide 1000 by the number of read
        // operations to obtain the interval in milliseconds
        int interval = 1000 / ((_binaryBaudRate / 10) / len);
        _readTickTimer.start(interval / _replayAccelerationFactor);
    }
    
    emit playbackStarted();
}

void LogReplayLink::_pause(void)
{
427
    qgcApp()->toolbox()->linkManager()->setConnectionsAllowed();
Don Gagne's avatar
Don Gagne committed
428
#ifndef __mobile__
429
    qgcApp()->toolbox()->mavlinkProtocol()->suspendLogForReplay(false);
Don Gagne's avatar
Don Gagne committed
430
#endif
Don Gagne's avatar
Don Gagne committed
431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468
    
    _readTickTimer.stop();
    
    emit playbackPaused();
}

void LogReplayLink::_resetPlaybackToBeginning(void)
{
    if (_logFile.isOpen()) {
        _logFile.reset();
    }
    
    // And since we haven't starting playback, clear the time of initial playback and the current timestamp.
    _playbackStartTimeMSecs = 0;
    _logCurrentTimeUSecs = _logStartTimeUSecs;
}

void LogReplayLink::movePlayhead(int percentComplete)
{
    if (isPlaying()) {
        qWarning() << "Should not move playhead while playing, pause first";
        return;
    }

    if (percentComplete < 0 || percentComplete > 100) {
        qWarning() << "Bad percentage value" << percentComplete;
        return;
    }
    
    float floatPercentComplete = (float)percentComplete / 100.0f;
    
    if (_logTimestamped) {
        // But if we have a timestamped MAVLink log, then actually aim to hit that percentage in terms of
        // time through the file.
        qint64 newFilePos = (qint64)(floatPercentComplete * (float)_logFile.size());
        
        // Now seek to the appropriate position, failing gracefully if we can't.
        if (!_logFile.seek(newFilePos)) {
469
            _replayError(tr("Unable to seek to new position"));
Don Gagne's avatar
Don Gagne committed
470 471 472 473 474 475 476 477 478 479 480 481 482 483 484 485 486 487 488
            return;
        }
        
        // But we do align to the next MAVLink message for consistency.
        mavlink_message_t dummy;
        _logCurrentTimeUSecs = _seekToNextMavlinkMessage(&dummy);
        
        // Now calculate the current file location based on time.
        float newRelativeTimeUSecs = (float)(_logCurrentTimeUSecs - _logStartTimeUSecs);
        
        // Calculate the effective baud rate of the file in bytes/s.
        float baudRate = _logFile.size() / (float)_logDurationUSecs / 1e6;
        
        // And the desired time is:
        float desiredTimeUSecs = floatPercentComplete * _logDurationUSecs;
        
        // And now jump the necessary number of bytes in the proper direction
        qint64 offset = (newRelativeTimeUSecs - desiredTimeUSecs) * baudRate;
        if (!_logFile.seek(_logFile.pos() + offset)) {
489
            _replayError(tr("Unable to seek to new position"));
Don Gagne's avatar
Don Gagne committed
490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507
            return;
        }
        
        // And scan until we reach the start of a MAVLink message. We make sure to record this timestamp for
        // smooth jumping around the file.
        _logCurrentTimeUSecs = _seekToNextMavlinkMessage(&dummy);
        
        // Now update the UI with our actual final position.
        newRelativeTimeUSecs = (float)(_logCurrentTimeUSecs - _logStartTimeUSecs);
        percentComplete = (newRelativeTimeUSecs / _logDurationUSecs) * 100;
        emit playbackPercentCompleteChanged(percentComplete);
    } else {
        // If we're working with a non-timestamped file, we just jump to that percentage of the file,
        // align to the next MAVLink message and roll with it. No reason to do anything more complicated.
        qint64 newFilePos = (qint64)(floatPercentComplete * (float)_logFile.size());
        
        // Now seek to the appropriate position, failing gracefully if we can't.
        if (!_logFile.seek(newFilePos)) {
508
            _replayError(tr("Unable to seek to new position"));
Don Gagne's avatar
Don Gagne committed
509 510 511 512 513 514 515 516 517 518 519 520 521 522 523 524 525 526 527 528 529 530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551 552 553 554 555 556 557 558 559 560 561
            return;
        }
        
        // But we do align to the next MAVLink message for consistency.
        mavlink_message_t dummy;
        _seekToNextMavlinkMessage(&dummy);
    }
}

void LogReplayLink::_setAccelerationFactor(int factor)
{
    // factor: -100: 0.01X, 0: 1.0X, 100: 100.0X
    
    if (factor < 0) {
        _replayAccelerationFactor = 0.01f;
        factor -= -100;
        if (factor > 0) {
            _replayAccelerationFactor *= (float)factor;
        }
    } else if (factor > 0) {
        _replayAccelerationFactor = 1.0f * (float)factor;
    } else {
        _replayAccelerationFactor = 1.0f;
    }
    
    // Update timer interval
    if (!_logTimestamped) {
        // Read len bytes at a time
        int len = 100;
        // Calculate the number of times to read 100 bytes per second
        // to guarantee the baud rate, then divide 1000 by the number of read
        // operations to obtain the interval in milliseconds
        int interval = 1000 / ((_binaryBaudRate / 10) / len);
        _readTickTimer.stop();
        _readTickTimer.start(interval / _replayAccelerationFactor);
    }
}

/// @brief Called when playback is complete
void LogReplayLink::_finishPlayback(void)
{
    _pause();
    
    emit playbackAtEnd();
}

/// @brief Called when an error occurs during playback to reset playback system state.
void LogReplayLink::_playbackError(void)
{
    _pause();
    _logFile.close();
    emit playbackError();
}