MongoDB 4.4+ logs are not supported by compat-tool about amazon-documentdb-tools HOT 15 CLOSED

@ylittman the lines skipped in your log are not due to truncation (which requires the parameter to be changed) but rather they were missing a timestamp as the beginning of the log.

Please pull and rerun the code, I added a feature to log all "skipped" lines to a log file with the extension ".skipped". You can then see the exact lines that were skipped in your logs.

from amazon-documentdb-tools.

@tmcallaghan Thank you for your quick response. I got the .skipped file which indicated all lines skipped.

fname = /Users/ylittman/Downloads/log2000.o | line number = 1 | reason = unrecognized line
....
fname = /Users/ylittman/Downloads/log2000.o | line number = 200 | reason = unrecognized line

Any suggestion? Thanks again.

from amazon-documentdb-tools.

Right after each of these lines in the skipped file it includes the actual line from the log file? Can you look at each to see what the log line actually is?

from amazon-documentdb-tools.

@ylittman any update?

from amazon-documentdb-tools.

@tmcallaghan Here is a few examples:
fname = /Users/ylittman/Downloads/log2000.o | line number = 1 | reason = unrecognized line
Actual Line | {"t":{"$date":"2021-11-01T08:45:34.053-07:00"},"s":"I", "c":"TXN", "id":51802, "ctx":"conn17021","msg":"transaction","attr":{"parameters":{"lsid":{"id":{"$uuid":"c3d6c16b-be4b-4d6f-9131-01e1c027f3fe"},"uid":{"$binary":{"base64":"K7CVfh3FRef+S1as8m9t7MAFUcYR4kNDUv9YVpq9JGg=","subType":"0"}}},"txnNumber":833929,"autocommit":false,"readConcern":{"provenance":"implicitDefault"}},"readTimestamp":"Timestamp(0, 0)","terminationCause":"committed","timeActiveMicros":571,"timeInactiveMicros":1404,"numYields":0,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":2}},"Global":{"acquireCount":{"w":1}},"Database":{"acquireCount":{"w":2}},"Collection":{"acquireCount":{"w":2}},"Mutex":{"acquireCount":{"r":2}}},"storage":{},"wasPrepared":false,"durationMillis":1}}

fname = /Users/ylittman/Downloads/log2000.o | line number = 3 | reason = unrecognized line
Actual Line | {"t":{"$date":"2021-11-01T08:45:34.053-07:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn1406","msg":"Slow query","attr":{"type":"command","ns":"local.oplog.rs","appName":"OplogFetcher","command":{"getMore":1537880459821048813,"collection":"oplog.rs","batchSize":13981010,"maxTimeMS":5000,"term":2,"lastKnownCommittedOpTime":{"ts":{"$timestamp":{"t":0,"i":0}},"t":-1},"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1634224301,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}}},"originatingCommand":{"find":"oplog.rs","filter":{"ts":{"$gte":{"$timestamp":{"t":1634197575,"i":1}}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}}},"ntoreturn":13981010,"maxTimeMS":60000,"tailable":true,"awaitData":true,"oplogReplay":true,"term":2,"$db":"local","$replData":1,"$oplogQueryData":1,"$readPreference":{"mode":"secondaryPreferred"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1634224301,"i":2}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}}},"planSummary":"COLLSCAN","cursorid":1537880459821048813,"keysExamined":0,"docsExamined":1,"numYields":4,"nreturned":1,"reslen":1098,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":5}},"Global":{"acquireCount":{"r":5}},"Database":{"acquireCount":{"r":5}},"Mutex":{"acquireCount":{"r":1}},"oplog":{"acquireCount":{"r":5}}},"readConcern":{"level":"local","afterClusterTime":{"$timestamp":{"t":0,"i":1}},"provenance":"clientSupplied"},"storage":{},"protocol":"op_msg","durationMillis":0}}

Actual Line | {"t":{"$date":"2021-11-01T08:45:35.067-07:00"},"s":"I", "c":"WRITE", "id":51803, "ctx":"conn17021","msg":"Slow query","attr":{"type":"update","ns":"pw_collected_sample_bc_command_sat.lock","command":{"q":{"_id":"event-publisher","$or":[{"masterId":"3c9dad55-fa2b-49eb-83a7-01f6d510a05a"},{"lockTimestamp":{"$lt":1635781530054}}]},"u":{"$set":{"masterId":"3c9dad55-fa2b-49eb-83a7-01f6d510a05a","lockTimestamp":1635781535054}},"multi":false,"upsert":false},"planSummary":"IXSCAN { _id: 1 }","keysExamined":1,"docsExamined":1,"nMatched":1,"nModified":1,"numYields":0,"queryHash":"D7896295","planCacheKey":"9A29AC8B","locks":{"Database":{"acquire
Count":{"w":1}},"Collection":{"acquireCount":{"w":1}},"Mutex":{"acquireCount":{"r":1}}},"flowControl":{"acquireCount":1},"storage":{},"durationMillis":0}}

Thank you!

from amazon-documentdb-tools.

@ylittman the mtools.util logevent parser is unable to find a usable timestamp from these log lines so they are skipped by the compatibility tool. They can be ignored.

from amazon-documentdb-tools.

Thank you @tmcallaghan . Can we still depend on the compatibility tool 100% since some of transactions miss usable timestamps? Or we can use it as a complement tool? Thank you again.

from amazon-documentdb-tools.

@tmcallaghan Do you have an example of usable timestamp used by mtools.util logevent parser? Thanks again.

from amazon-documentdb-tools.

@ylittman based on your above output it appears that line 1 from your log was skipped, line 2 was not, line 3 was skipped, etc. Can you review the first 10 lines of your log for anything proprietary (feel free to xxxxxxxxx out any of it) and paste them into this issue? I'm pretty sure these extra lines are your server logging for other purposes that are not relevant to compatibility checking. Also, this tool is meant to be a tool in the compatibility checking process, not a replacement for testing your workload on DocumentDB. Make sure you do both.

from amazon-documentdb-tools.

@tmcallaghan Actually all lines are skipped. I just took some excerpts from the output. Do you have any example of "good" outputs? Thank you again.

from amazon-documentdb-tools.

@ylittman what version of MongoDB are you running?

from amazon-documentdb-tools.

@tmcallaghan The log I used was generated on mongodb 4.4. Thanks again.

from amazon-documentdb-tools.

@ylittman I just ran a test on my local MongoDB 4.4 server and can see that the logging format has changed significantly in 4.4+. I need to take a look at the code to see what needs change to be 4.4+ compatible. I'll use this issue to track my progress and close it when 4.4+ works. The good news is that 4.4 logging is much cleaner and appears to have fixed the issue where internal double quotes are now properly escaped.

from amazon-documentdb-tools.

Thank you very much @tmcallaghan
Hope it will work for both 4.2 and 4.4.

from amazon-documentdb-tools.

Fixed via #37

from amazon-documentdb-tools.