[SERVER-9102] Improve Format of OpTime (Timestamp) Strings Created: 23/Mar/13  Updated: 06/Dec/22  Resolved: 31/Aug/17

Status: Closed
Project: Core Server
Component/s: Internal Code, Logging
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Trivial - P5
Reporter: Scott Hernandez (Inactive) Assignee: Backlog - Replication Team
Resolution: Duplicate Votes: 1
Labels: neweng
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-27814 Make timestamp logging format consistent Closed
is duplicated by SERVER-14428 Display OpTime in decimal Closed
Related
is related to SERVER-9101 Formatting issues with initialSyncOpl... Closed
Assigned Teams:
Replication
Backwards Compatibility: Fully Compatible
Participants:

 Description   

Optime.toStringPretty() should look like this:

Mar 21 05:31:25 (a1)

Instead of this one which looks like "a1" (the increment) is the milliseconds fields.

Mar 21 05:31:25:a1



 Comments   
Comment by Matt Kangas [ 21/Aug/13 ]

Places where this change will be used:

OpTime.toStringPretty

$ git grep toStringPretty
src/mongo/bson/optime.h:        string toStringPretty() const {
src/mongo/db/pipeline/value.cpp:            ss << getTimestamp().toStringPretty();
src/mongo/db/repl/bgsync.cpp:            log() << "replSet our last op time fetched: " << _lastOpTimeFetched.toStringPretty() << rsLog;
src/mongo/db/repl/bgsync.cpp:            log() << "replset source's GTE: " << ts.toStringPretty() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:            log() << "replSet info rollback our last optime:   " << ourTime.toStringPretty() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:            log() << "replSet info rollback their last optime: " << theirTime.toStringPretty() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet rollback found matching events at " << ourTime.toStringPretty() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:        LOG(2) << "replSet rollback truncate oplog after " << h.commonPoint.toStringPretty() << rsLog;
src/mongo/db/repl/rs_sync.cpp:                          << ts.toStringPretty() << rsLog;
src/mongo/dbtests/documenttests.cpp:                string expected() { return OpTime( 1, 2 ).toStringPretty(); }
src/mongo/tools/oplog.cpp:        log() << "starting from " << start.toStringPretty() << endl;

OpTime.toStringLong

$ git grep toStringLong
src/mongo/bson/optime.h:        string toStringLong() const {
src/mongo/client/dbclientinterface.h:        string toStringLong() const {
src/mongo/db/repl/bgsync.cpp:            log() << "replSet remoteOldestOp:    " << remoteTs.toStringLong() << rsLog;
src/mongo/db/repl/bgsync.cpp:            log() << "replSet lastOpTimeFetched: " << _lastOpTimeFetched.toStringLong() << rsLog;
src/mongo/db/repl/bgsync.cpp:        LOG(3) << "replSet remoteOldestOp: " << remoteTs.toStringLong() << rsLog;
src/mongo/db/repl/master_slave.cpp:        LOG(2) << "repl: sync_pullOpLog " << ns << " syncedTo:" << syncedTo.toStringLong() << '\n';
src/mongo/db/repl/master_slave.cpp:                    log() << "repl syncTo:     " << syncedTo.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                    log() << "repl nextOpTime: " << nextOpTime.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                    << "repl:   nextOpTime " << nextOpTime.toStringLong() << ' '
src/mongo/db/repl/master_slave.cpp:                    << " syncedTo " << syncedTo.toStringLong() << '\n'
src/mongo/db/repl/master_slave.cpp:                    log() << "repl:  end sync_pullOpLog syncedTo: " << syncedTo.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                    log() << "repl:   syncedTo: " << syncedTo.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                        log() << " last:       " << last.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                        log() << " nextOpTime: " << nextOpTime.toStringLong() << endl;
src/mongo/db/repl/master_slave.cpp:                        log() << "repl:   syncedTo: " << syncedTo.toStringLong() << endl;
src/mongo/db/repl/rs.cpp:        log() << "replSet our last optime : " << lastOpTimeWritten.toStringLong() << rsLog;
src/mongo/db/repl/rs.cpp:        log() << "replSet oldest at " << stale->fullName() << " : " << oldest["ts"]._opTime().toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   theirTime: " << theirTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                    log() << "replSet   ourTime:   " << ourTime.toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:        log() << "replSet minvalid=" << newMinValid["ts"]._opTime().toStringLong() << rsLog;
src/mongo/db/repl/rs_rollback.cpp:                        log() << "replSet minvalid=" << newMinValid["ts"]._opTime().toStringLong() << rsLog;

OpTime.toString... harder to search for usages

Comment by Eric Daniels (Inactive) [ 23/Jul/13 ]

Pull Request:
https://github.com/mongodb/mongo/pull/461

Comment by Eric Daniels (Inactive) [ 23/Jul/13 ]

Before:

toStringLong(): Mar 21 05:31:25 514a9b2d:a1
toStringPretty(): Mar 21 05:31:25:a1
toString(): 514a9b2d:a1

After:

toStringLong(): Mar 21 05:31:25 514a9b2d (a1)
toStringPretty(): Mar 21 05:31:25 (a1)
toString(): 514a9b2d (a1)

Comment by Scott Hernandez (Inactive) [ 23/Jul/13 ]

Yep, we can clean them all up and get rid of the unused char[] also.

Can you post the outputs from each before and after for posterity?

Comment by Eric Daniels (Inactive) [ 23/Jul/13 ]

Should we change OpTime.toString() and OpTime.toStringLong() to reflect this as well? The only difference in these two is that there is only one : separator and both values are hex; could still be confusing. Also for clarification, OpTime.toStringLong() sets up a buffer for use with time_t_to_String but never uses it. Instead, it uses time_t_to_String_short() for printing secs.

Looks like it should be (disregarding () for ordinal):

string toStringLong() const {
    char buf[64];
    time_t_to_String(secs, buf);
    std::stringstream ss;
    ss << buf << ' ';
    ss << std::hex << secs << ':' << i;
    return ss.str();
}

Generated at Thu Feb 08 03:19:23 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.