Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Drop a capped collection #1745

Closed
acrozes opened this issue Feb 23, 2018 · 11 comments
Closed

Drop a capped collection #1745

acrozes opened this issue Feb 23, 2018 · 11 comments

Comments

@acrozes
Copy link

acrozes commented Feb 23, 2018

Using drop functions from Doctrine\ODM\MongoDB\SchemaManager on a capped collection return now an error with mongoDB 3.6:

cannot remove from a capped collection: collectionName => drop collection

So how to remove a capped collection ?
Thank you

@malarzm
Copy link
Member

malarzm commented Feb 23, 2018

From what I see in MongoDB documentation drop() should work just fine with capped collections, can you please create a failing test case?

@jmikola
Copy link
Member

jmikola commented Feb 23, 2018

As discussed in Document Deletion, individual documents cannot be removed but there should be no issue dropping the collection itself.

Best I can tell, when SchemaCollection drops a document collection, it ultimately invokes MongoCollection::drop() through Doctrine/MongoDB/Collection, which should still be compatible with MongoDB 3.6.

@acrozes
Copy link
Author

acrozes commented Feb 24, 2018

Versions:
php: 7.2
sf 3.4.4
mongodb/mongodb: 1.3.0
doctrine/mongodb-odm-bundle: 3.4.1
doctrine/mongodb-odm: 1.2.1
doctrine/mongodb: 1.6.1
alcaeus/mongo-php-adapter: 1.1.4

Document:

use Doctrine\ODM\MongoDB\Mapping\Annotations as MongoDB;

/**
 * @MongoDB\Document(
 *  collection={
 *   "name"="logs",
 *   "capped"=true,
 *   "size"=1073741824,
 *   "max"=3000000
 *  }
 * )
 */
class Log
{
    /**
     * @MongoDB\Id
     */
    protected $id;
[...]

The command I execute and that failed:

    protected function execute(InputInterface $input, OutputInterface $output): void
    {
        // TODO fix dropDocumentCollection for capped collection
        $this->dm->getSchemaManager()->dropDocumentCollection(Log::class);
        $this->dm->getSchemaManager()->dropDocumentDatabase(Log::class);
        $this->dm->getSchemaManager()->dropDatabases();
    }

The three called failed: dropDocumentCollection, dropDocumentDatabase or dropDatabases with message: cannot remove from a capped collection

@jmikola
Copy link
Member

jmikola commented Feb 27, 2018

I'm unable to reproduce with the following environment and test case:

  • MongoDB 3.6.0
  • PHP 7.2.0
  • doctrine/mongodb-odm: 1.2.1
  • doctrine/mongodb: 1.6.1
  • alcaeus/mongo-php-adapter: 1.1.4
<?php

namespace Doctrine\ODM\MongoDB\Tests\Functional;

use Doctrine\ODM\MongoDB\Mapping\Annotations as ODM;

class GH1745Test extends \Doctrine\ODM\MongoDB\Tests\BaseTest
{
    public function testCreateCollectionsCapped()
    {
        $sm = $this->dm->getSchemaManager();
        $sm->dropDocumentCollection(GH1745Document::class);
        $sm->createDocumentCollection(GH1745Document::class);

        foreach (['a', 'b', 'c'] as $username) {
            $document = new GH1745Document;
            $document->username = $username;
            $this->dm->persist($document);
        }

        $this->dm->flush();

        $coll = $this->dm->getDocumentCollection(GH1745Document::class);
        $this->assertCount(3, $coll->find()->toArray());
exit;
        $this->dm->getSchemaManager()->dropDocumentCollection(GH1745Document::class);
        $this->dm->getSchemaManager()->dropDocumentDatabase(GH1745Document::class);
        $this->dm->getSchemaManager()->dropDatabases();
    }
}

/**
 * @ODM\Document(collection={
 *   "name"="GH1745Document",
 *   "capped"=true,
 *   "size"=1073741824,
 *   "max"=3000000
 * })
 */
class GH1745Document
{
    /** @ODM\Id */
    public $id;

    /** @ODM\Field(type="string") */
    public $username;
}

If I interrupt the script with exit() before invoking the drop methods on the SchemaManager, I can verify that the following capped collection exists on the server:

> db.getSiblingDB('doctrine_odm_tests').getCollectionInfos()
[
	{
		"name" : "GH1745Document",
		"type" : "collection",
		"options" : {
			"capped" : true,
			"size" : 1073741824,
			"max" : 3000000
		},
		"info" : {
			"readOnly" : false,
			"uuid" : UUID("8cd3b2a2-f270-4b8c-bfb7-bdffda197eaf")
		},
		"idIndex" : {
			"v" : 2,
			"key" : {
				"_id" : 1
			},
			"name" : "_id_",
			"ns" : "doctrine_odm_tests.GH1745Document"
		}
	}
]

The error message "cannot remove from a capped collection" evidently originates from the server and appears twice in its code base:

The message templating in collection_impl.cpp does not report the collection name after a colon (although the mongod logging on the preceding line does), so I assume this is originating from get_executor.cpp. Following the rabbit hole, getExecutorDelete() is called from three places:

write_commands.cpp relates to explaining a delete command, storage_interface_impl.cpp is related to internal replication, and find_and_modify.cpp is self-explanatory. I don't think these are relevant.

delete.cpp contains a helper function called deleteObjects(), which is used internally by replication (mostly to delete the "local.me" namespace from what I can tell). That leaves write_ops_exec.cpp, which is related to the code path of a delete command.

That said, I still see no evidence of delete being called in this issue, as the schema managers use drop commands.

The three called failed: dropDocumentCollection, dropDocumentDatabase or dropDatabases with message: cannot remove from a capped collection

What is the complete exception (message and integer code) and full back trace? On the off chance that contains some useful information, my next question is going to be why wasn't that included in the original post.

@acrozes
Copy link
Author

acrozes commented Feb 27, 2018

Thank you for your work.
I manualy drop the database and now I'm unable to reproduce it.
Something more strange is that the collection was not capped in mongoDb, so the message was completly incomprehensible !
This is true that we can have defined a capped collection and when the collection is really created in mongoDb by default the collection is not capped ...

@jmikola
Copy link
Member

jmikola commented Feb 27, 2018

Are you still able to share the complete exception and back trace, or are we never going to get to see that? I was very much looking forward to seeing that, as it'd have cleared up a lot of questions.

Something more strange is that the collection was not capped in mongoDb, so the message was completly incomprehensible !

If the MongoDB collection was not capped, I can think of no reason for "cannot remove from a capped collection" to appear. This issue is missing too many details.

It was helpful for you to provide version information in #1745 (comment), but ideally that should appear in the original post. Additionally, you should provide details about the MongoDB deployment, connection URI/options, and above all else: the exception message and back trace. Please keep this in mind in the future.

This is true that we can have defined a capped collection and when the collection is really created in mongoDb by default the collection is not capped ...

AFAIK, the collection options in ODM are only used by the SchemaManager classes and it is your responsibility to run the schema commands.

If you create new objects for a model class that defines collection.capped=true and persist those with the DocumentManager, ODM will simply execute an insert operation as it has no way of knowing whether the collection exists or not. To that end, inserting a document into a non-existent collection will see MongoDB create a basic collection (standard behavior for the database).

While ODM theoretically could check for the existence of a collection (e.g. call the equivalent of getCollectionInfos() in the shell) and verify that its options match the metadata, doing this before write operations would incur significant overhead.

@acrozes
Copy link
Author

acrozes commented Feb 28, 2018

I'm sorry, I haven't more logs when the erreur occur and the collection was drop with the database after I rename it and try again the command :(
The collection was created on MongoDB 3.4 or maybe 3.2 and now I am on 3.6 so maybe the error is in link with changing version ...
If that can help you, 2 more informations:

  • the logs of the mongo driver when I execute the same commande now:
[localhost] > php "./bin/console"  ac:monolog:create --env=prod
[localhost] < Deprecated: Directive 'track_errors' is deprecated in Unknown on line 0
[localhost] < [2018-02-28T00:23:53.442076+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://127.0.0.1:27017'
[localhost] < [2018-02-28T00:23:53.442443+00:00]     PHONGO: DEBUG   > Creating Manager, phongo-1.4.1[stable] - mongoc-1.9.2(bundled), libbson-1.9.2(bundled), php-7.2.1-dev
[localhost] < [2018-02-28T00:23:53.442926+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_init():75
[localhost] < [2018-02-28T00:23:53.449278+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_init():94
[localhost] < [2018-02-28T00:23:53.449496+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_init():104
[localhost] < [2018-02-28T00:23:53.449617+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_init():123
[localhost] < [2018-02-28T00:23:53.449902+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_init():1867
[localhost] < [2018-02-28T00:23:53.449984+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_init():1894
[localhost] < [2018-02-28T00:23:53.450037+00:00]     PHONGO: DEBUG   > Created client hash: a:4:{s:3:"pid";i:13820;s:3:"uri";s:25:"mongodb://127.0.0.1:27017";s:7:"options";a:1:{s:7:"connect";b:1;}s:13:"driverOptions";a:0:{}}
[localhost] < [2018-02-28T00:23:53.548632+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://127.0.0.1:27017'
[localhost] < [2018-02-28T00:23:53.548702+00:00]     PHONGO: DEBUG   > Creating Manager, phongo-1.4.1[stable] - mongoc-1.9.2(bundled), libbson-1.9.2(bundled), php-7.2.1-dev
[localhost] < [2018-02-28T00:23:53.548742+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_init():75
[localhost] < [2018-02-28T00:23:53.548777+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_init():94
[localhost] < [2018-02-28T00:23:53.548827+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_init():104
[localhost] < [2018-02-28T00:23:53.548861+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_init():123
[localhost] < [2018-02-28T00:23:53.548900+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_init():1867
[localhost] < [2018-02-28T00:23:53.548934+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_init():1894
[localhost] < [2018-02-28T00:23:53.548964+00:00]     PHONGO: DEBUG   > Created client hash: a:4:{s:3:"pid";i:13820;s:3:"uri";s:25:"mongodb://127.0.0.1:27017";s:7:"options";a:0:{}s:13:"driverOptions";a:0:{}}
[localhost] < [2018-02-28T00:23:53.567706+00:00] topology_scanner: TRACE   > ENTRY: mongoc_topology_scanner_node_connect_tcp():468
[localhost] < [2018-02-28T00:23:53.567815+00:00]     socket: TRACE   > ENTRY: mongoc_socket_new():977
[localhost] < [2018-02-28T00:23:53.568337+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_setnodelay():556
[localhost] < [2018-02-28T00:23:53.568409+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_setnodelay():568
[localhost] < [2018-02-28T00:23:53.568438+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_setkeepalive():521
[localhost] < [2018-02-28T00:23:53.568480+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive():525 Setting SO_KEEPALIVE
[localhost] < [2018-02-28T00:23:53.568608+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():420 KeepAlive values updated
[localhost] < [2018-02-28T00:23:53.568650+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():421 KeepAliveTime: 300000
[localhost] < [2018-02-28T00:23:53.568679+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():422 KeepAliveInterval: 1000
[localhost] < [2018-02-28T00:23:53.568704+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_setkeepalive():537
[localhost] < [2018-02-28T00:23:53.568727+00:00]     socket: TRACE   >  EXIT: mongoc_socket_new():1009
[localhost] < [2018-02-28T00:23:53.568761+00:00]     socket: TRACE   > ENTRY: mongoc_socket_connect():840
[localhost] < [2018-02-28T00:23:53.569376+00:00]     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():68 setting errno: 10035 Unknown error
[localhost] < [2018-02-28T00:23:53.569476+00:00]     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():617 errno is: 10035
[localhost] < [2018-02-28T00:23:53.569528+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_wait():148
[localhost] < [2018-02-28T00:23:53.569639+00:00]     socket: TRACE   >  EXIT: mongoc_socket_connect():865
[localhost] < [2018-02-28T00:23:53.569778+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_poll():223
[localhost] < [2018-02-28T00:23:53.569830+00:00]     socket: TRACE   > ENTRY: mongoc_socket_poll():283
[localhost] < [2018-02-28T00:23:53.569888+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_poll():249
[localhost] < [2018-02-28T00:23:53.570091+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[localhost] < [2018-02-28T00:23:53.570163+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 000000C210C0A410 [9]
[localhost] < [2018-02-28T00:23:53.570283+00:00]     stream: TRACE   > 00000:  50 01 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  P . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:53.570411+00:00]     stream: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
[localhost] < [2018-02-28T00:23:53.570487+00:00]     stream: TRACE   > 00020:  00 00 00 ff ff ff ff 29  01 00 00 10 69 73 4d 61  . . . ▒ ▒ ▒ ▒ )  . . . . i s M a
[localhost] < [2018-02-28T00:23:53.570585+00:00]     stream: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 03 63 6c 69 65 6e 74  s t e r . . . .  . . c l i e n t
[localhost] < [2018-02-28T00:23:53.570688+00:00]     stream: TRACE   > 00040:  00 fc 00 00 00 03 64 72  69 76 65 72 00 43 00 00  . ▒ . . . . d r  i v e r . C . .
[localhost] < [2018-02-28T00:23:53.570764+00:00]     stream: TRACE   > 00050:  00 02 6e 61 6d 65 00 19  00 00 00 6d 6f 6e 67 6f  . . n a m e . .  . . . m o n g o
[localhost] < [2018-02-28T00:23:53.570839+00:00]     stream: TRACE   > 00060:  63 20 2f 20 65 78 74 2d  6d 6f 6e 67 6f 64 62 3a  c   /   e x t -  m o n g o d b :
[localhost] < [2018-02-28T00:23:53.570907+00:00]     stream: TRACE   > 00070:  50 48 50 00 02 76 65 72  73 69 6f 6e 00 0e 00 00  P H P . . v e r  s i o n . . . .
[localhost] < [2018-02-28T00:23:53.570978+00:00]     stream: TRACE   > 00080:  00 31 2e 39 2e 32 20 2f  20 31 2e 34 2e 31 00 00  . 1 . 9 . 2   /    1 . 4 . 1 . .
[localhost] < [2018-02-28T00:23:53.571044+00:00]     stream: TRACE   > 00090:  03 6f 73 00 5a 00 00 00  02 74 79 70 65 00 08 00  . o s . Z . . .  . t y p e . . .
[localhost] < [2018-02-28T00:23:53.571113+00:00]     stream: TRACE   > 000a0:  00 00 57 69 6e 64 6f 77  73 00 02 6e 61 6d 65 00  . . W i n d o w  s . . n a m e .
[localhost] < [2018-02-28T00:23:53.571181+00:00]     stream: TRACE   > 000b0:  08 00 00 00 57 69 6e 64  6f 77 73 00 02 76 65 72  . . . . W i n d  o w s . . v e r
[localhost] < [2018-02-28T00:23:53.571250+00:00]     stream: TRACE   > 000c0:  73 69 6f 6e 00 0b 00 00  00 36 2e 33 20 28 39 36  s i o n . . . .  . 6 . 3   ( 9 6
[localhost] < [2018-02-28T00:23:53.571321+00:00]     stream: TRACE   > 000d0:  30 30 29 00 02 61 72 63  68 69 74 65 63 74 75 72  0 0 ) . . a r c  h i t e c t u r
[localhost] < [2018-02-28T00:23:53.571387+00:00]     stream: TRACE   > 000e0:  65 00 07 00 00 00 78 38  36 5f 36 34 00 00 02 70  e . . . . . x 8  6 _ 6 4 . . . p
[localhost] < [2018-02-28T00:23:53.571457+00:00]     stream: TRACE   > 000f0:  6c 61 74 66 6f 72 6d 00  40 00 00 00 63 66 67 3d  l a t f o r m .  @ . . . c f g =
[localhost] < [2018-02-28T00:23:53.571531+00:00]     stream: TRACE   > 00100:  30 78 34 30 32 61 30 65  39 20 43 43 3d 4d 53 56  0 x 4 0 2 a 0 e  9   C C = M S V
[localhost] < [2018-02-28T00:23:53.571606+00:00]     stream: TRACE   > 00110:  43 20 31 39 31 32 20 43  46 4c 41 47 53 3d 22 22  C   1 9 1 2   C  F L A G S = " "
[localhost] < [2018-02-28T00:23:53.571682+00:00]     stream: TRACE   > 00120:  20 4c 44 46 4c 41 47 53  3d 22 22 20 2f 20 50 48    L D F L A G S  = " "   /   P H
[localhost] < [2018-02-28T00:23:53.571766+00:00]     stream: TRACE   > 00130:  50 20 37 2e 32 2e 31 2d  64 65 76 00 00 04 63 6f  P   7 . 2 . 1 -  d e v . . . c o
[localhost] < [2018-02-28T00:23:53.571842+00:00]     stream: TRACE   > 00140:  6d 70 72 65 73 73 69 6f  6e 00 05 00 00 00 00 00  m p r e s s i o  n . . . . . . .
[localhost] < [2018-02-28T00:23:53.571875+00:00]     stream: TRACE   >
[localhost] < [2018-02-28T00:23:53.571904+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[localhost] < [2018-02-28T00:23:53.571930+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[localhost] < [2018-02-28T00:23:53.571956+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[localhost] < [2018-02-28T00:23:53.571984+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 000000C210B7E5E0 [9]
[localhost] < [2018-02-28T00:23:53.572048+00:00]     socket: TRACE   > 00000:  50 01 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  P . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:53.572117+00:00]     socket: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
[localhost] < [2018-02-28T00:23:53.572271+00:00]     socket: TRACE   > 00020:  00 00 00 ff ff ff ff 29  01 00 00 10 69 73 4d 61  . . . ▒ ▒ ▒ ▒ )  . . . . i s M a
[localhost] < [2018-02-28T00:23:53.572350+00:00]     socket: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 03 63 6c 69 65 6e 74  s t e r . . . .  . . c l i e n t
[localhost] < [2018-02-28T00:23:53.572417+00:00]     socket: TRACE   > 00040:  00 fc 00 00 00 03 64 72  69 76 65 72 00 43 00 00  . ▒ . . . . d r  i v e r . C . .
[localhost] < [2018-02-28T00:23:53.572484+00:00]     socket: TRACE   > 00050:  00 02 6e 61 6d 65 00 19  00 00 00 6d 6f 6e 67 6f  . . n a m e . .  . . . m o n g o
[localhost] < [2018-02-28T00:23:53.572558+00:00]     socket: TRACE   > 00060:  63 20 2f 20 65 78 74 2d  6d 6f 6e 67 6f 64 62 3a  c   /   e x t -  m o n g o d b :
[localhost] < [2018-02-28T00:23:53.572626+00:00]     socket: TRACE   > 00070:  50 48 50 00 02 76 65 72  73 69 6f 6e 00 0e 00 00  P H P . . v e r  s i o n . . . .
[localhost] < [2018-02-28T00:23:53.572697+00:00]     socket: TRACE   > 00080:  00 31 2e 39 2e 32 20 2f  20 31 2e 34 2e 31 00 00  . 1 . 9 . 2   /    1 . 4 . 1 . .
[localhost] < [2018-02-28T00:23:53.572820+00:00]     socket: TRACE   > 00090:  03 6f 73 00 5a 00 00 00  02 74 79 70 65 00 08 00  . o s . Z . . .  . t y p e . . .
[localhost] < [2018-02-28T00:23:53.572991+00:00]     socket: TRACE   > 000a0:  00 00 57 69 6e 64 6f 77  73 00 02 6e 61 6d 65 00  . . W i n d o w  s . . n a m e .
[localhost] < [2018-02-28T00:23:53.573128+00:00]     socket: TRACE   > 000b0:  08 00 00 00 57 69 6e 64  6f 77 73 00 02 76 65 72  . . . . W i n d  o w s . . v e r
[localhost] < [2018-02-28T00:23:53.573259+00:00]     socket: TRACE   > 000c0:  73 69 6f 6e 00 0b 00 00  00 36 2e 33 20 28 39 36  s i o n . . . .  . 6 . 3   ( 9 6
[localhost] < [2018-02-28T00:23:53.573400+00:00]     socket: TRACE   > 000d0:  30 30 29 00 02 61 72 63  68 69 74 65 63 74 75 72  0 0 ) . . a r c  h i t e c t u r
[localhost] < [2018-02-28T00:23:53.574408+00:00]     socket: TRACE   > 000e0:  65 00 07 00 00 00 78 38  36 5f 36 34 00 00 02 70  e . . . . . x 8  6 _ 6 4 . . . p
[localhost] < [2018-02-28T00:23:53.574549+00:00]     socket: TRACE   > 000f0:  6c 61 74 66 6f 72 6d 00  40 00 00 00 63 66 67 3d  l a t f o r m .  @ . . . c f g =
[localhost] < [2018-02-28T00:23:53.575035+00:00]     socket: TRACE   > 00100:  30 78 34 30 32 61 30 65  39 20 43 43 3d 4d 53 56  0 x 4 0 2 a 0 e  9   C C = M S V
[localhost] < [2018-02-28T00:23:53.575188+00:00]     socket: TRACE   > 00110:  43 20 31 39 31 32 20 43  46 4c 41 47 53 3d 22 22  C   1 9 1 2   C  F L A G S = " "
[localhost] < [2018-02-28T00:23:53.575313+00:00]     socket: TRACE   > 00120:  20 4c 44 46 4c 41 47 53  3d 22 22 20 2f 20 50 48    L D F L A G S  = " "   /   P H
[localhost] < [2018-02-28T00:23:53.575438+00:00]     socket: TRACE   > 00130:  50 20 37 2e 32 2e 31 2d  64 65 76 00 00 04 63 6f  P   7 . 2 . 1 -  d e v . . . c o
[localhost] < [2018-02-28T00:23:53.575550+00:00]     socket: TRACE   > 00140:  6d 70 72 65 73 73 69 6f  6e 00 05 00 00 00 00 00  m p r e s s i o  n . . . . . . .
[localhost] < [2018-02-28T00:23:53.575591+00:00]     socket: TRACE   >
[localhost] < [2018-02-28T00:23:53.575761+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 336 (out of: 4), ret: 0
[localhost] < [2018-02-28T00:23:53.575815+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[localhost] < [2018-02-28T00:23:53.575863+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 336 (of 4) out of iovcnt=9
[localhost] < [2018-02-28T00:23:53.575909+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 336 -= 4
[localhost] < [2018-02-28T00:23:53.575955+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 332 -= 4
[localhost] < [2018-02-28T00:23:53.576000+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 328 -= 4
[localhost] < [2018-02-28T00:23:53.576047+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 324 -= 4
[localhost] < [2018-02-28T00:23:53.576094+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 320 -= 4
[localhost] < [2018-02-28T00:23:53.576144+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 316 -= 11
[localhost] < [2018-02-28T00:23:53.576206+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 305 -= 4
[localhost] < [2018-02-28T00:23:53.576333+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 301 -= 4
[localhost] < [2018-02-28T00:23:53.576402+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 297 -= 297
[localhost] < [2018-02-28T00:23:53.576455+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[localhost] < [2018-02-28T00:23:53.576504+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[localhost] < [2018-02-28T00:23:53.576555+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 10035
[localhost] < [2018-02-28T00:23:53.576602+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[localhost] < [2018-02-28T00:23:53.576649+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[localhost] < [2018-02-28T00:23:53.576698+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_poll():223
[localhost] < [2018-02-28T00:23:53.576739+00:00]     socket: TRACE   > ENTRY: mongoc_socket_poll():283
[localhost] < [2018-02-28T00:23:53.576813+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_poll():249
[localhost] < [2018-02-28T00:23:53.576947+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():336
[localhost] < [2018-02-28T00:23:53.576994+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[localhost] < [2018-02-28T00:23:53.577038+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[localhost] < [2018-02-28T00:23:53.577082+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[localhost] < [2018-02-28T00:23:53.577127+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[localhost] < [2018-02-28T00:23:53.577182+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[localhost] < [2018-02-28T00:23:53.577227+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[localhost] < [2018-02-28T00:23:53.577282+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000C20EB8DAA0 [1]
[localhost] < [2018-02-28T00:23:53.577360+00:00]     stream: TRACE   > 00000:  cd 00 00 00                                       ▒ . . .
[localhost] < [2018-02-28T00:23:53.577480+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[localhost] < [2018-02-28T00:23:53.577527+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[localhost] < [2018-02-28T00:23:53.577572+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():368
[localhost] < [2018-02-28T00:23:53.577618+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():336
[localhost] < [2018-02-28T00:23:53.577659+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[localhost] < [2018-02-28T00:23:53.577702+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[localhost] < [2018-02-28T00:23:53.577751+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[localhost] < [2018-02-28T00:23:53.577796+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[localhost] < [2018-02-28T00:23:53.577850+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[localhost] < [2018-02-28T00:23:53.577896+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[localhost] < [2018-02-28T00:23:53.577947+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000C20EB8DAA0 [1]
[localhost] < [2018-02-28T00:23:53.578067+00:00]     stream: TRACE   > 00000:  b4 c9 03 00 01 00 00 00  01 00 00 00 08 00 00 00  ▒ ▒ . . . . . .  . . . . . . . .
[localhost] < [2018-02-28T00:23:53.578175+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 00 00 00  00 00 00 00 01 00 00 00  . . . . . . . .  . . . . . . . .
[localhost] < [2018-02-28T00:23:53.578303+00:00]     stream: TRACE   > 00020:  a9 00 00 00 08 69 73 6d  61 73 74 65 72 00 01 10  ▒ . . . . i s m  a s t e r . . .
[localhost] < [2018-02-28T00:23:53.578445+00:00]     stream: TRACE   > 00030:  6d 61 78 42 73 6f 6e 4f  62 6a 65 63 74 53 69 7a  m a x B s o n O  b j e c t S i z
[localhost] < [2018-02-28T00:23:53.578684+00:00]     stream: TRACE   > 00040:  65 00 00 00 00 01 10 6d  61 78 4d 65 73 73 61 67  e . . . . . . m  a x M e s s a g
[localhost] < [2018-02-28T00:23:53.578822+00:00]     stream: TRACE   > 00050:  65 53 69 7a 65 42 79 74  65 73 00 00 6c dc 02 10  e S i z e B y t  e s . . l ▒ . .
[localhost] < [2018-02-28T00:23:53.579115+00:00]     stream: TRACE   > 00060:  6d 61 78 57 72 69 74 65  42 61 74 63 68 53 69 7a  m a x W r i t e  B a t c h S i z
[localhost] < [2018-02-28T00:23:53.579265+00:00]     stream: TRACE   > 00070:  65 00 a0 86 01 00 09 6c  6f 63 61 6c 54 69 6d 65  e . ▒ ▒ . .     l  o c a l T i m e
[localhost] < [2018-02-28T00:23:53.579395+00:00]     stream: TRACE   > 00080:  00 e8 47 cb d9 61 01 00  00 10 6d 69 6e 57 69 72  . ▒ G ▒ ▒ a . .  . . m i n W i r
[localhost] < [2018-02-28T00:23:53.579524+00:00]     stream: TRACE   > 00090:  65 56 65 72 73 69 6f 6e  00 00 00 00 00 10 6d 61  e V e r s i o n  . . . . . . m a
[localhost] < [2018-02-28T00:23:53.579657+00:00]     stream: TRACE   > 000a0:  78 57 69 72 65 56 65 72  73 69 6f 6e 00 06 00 00  x W i r e V e r  s i o n . . . .
[localhost] < [2018-02-28T00:23:53.579788+00:00]     stream: TRACE   > 000b0:  00 08 72 65 61 64 4f 6e  6c 79 00 00 01 6f 6b 00  . . r e a d O n  l y . . . o k .
[localhost] < [2018-02-28T00:23:53.579886+00:00]     stream: TRACE   > 000c0:  00 00 00 00 00 00 f0 3f  00                       . . . . . . ▒ ?  .
[localhost] < [2018-02-28T00:23:53.579939+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[localhost] < [2018-02-28T00:23:53.579980+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[localhost] < [2018-02-28T00:23:53.580025+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():368
[localhost] < [2018-02-28T00:23:53.580102+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:53.580169+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:53.580229+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1955 No transition entry to Single for Standalone
[localhost] < [2018-02-28T00:23:53.580296+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():798
[localhost] < [2018-02-28T00:23:53.580343+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():805
[localhost] < [2018-02-28T00:23:53.580394+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:53.580451+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:53.580500+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:53.580547+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:53.580621+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:53.580682+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:53.580762+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:53.580814+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:53.583853+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:53.583923+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:53.583970+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:53.583996+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:53.584071+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_opts():1724
[localhost] < [2018-02-28T00:23:53.584110+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[localhost] < [2018-02-28T00:23:53.584138+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():291
[localhost] < [2018-02-28T00:23:53.584169+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1650
[localhost] < [2018-02-28T00:23:53.584195+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1591
[localhost] < [2018-02-28T00:23:53.584229+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:53.584263+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:53.584295+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1617
[localhost] < [2018-02-28T00:23:53.584321+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1667
[localhost] < [2018-02-28T00:23:53.584365+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_append_opts():119
[localhost] < [2018-02-28T00:23:53.584403+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_append_opts():202
[localhost] < [2018-02-28T00:23:53.584434+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_stream():1603
[localhost] < [2018-02-28T00:23:53.584458+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_assemble():564
[localhost] < [2018-02-28T00:23:53.584484+00:00]     mongoc: TRACE   > TRACE: mongoc_cmd_parts_assemble():592 Preparing 'drop'
[localhost] < [2018-02-28T00:23:53.584526+00:00]     client: TRACE   > ENTRY: mongoc_client_start_session():1150
[localhost] < [2018-02-28T00:23:53.584552+00:00]     mongoc: TRACE   > ENTRY: _mongoc_topology_pop_server_session():1288
[localhost] < [2018-02-28T00:23:53.584583+00:00]     mongoc: TRACE   >  EXIT: _mongoc_topology_pop_server_session():1314
[localhost] < [2018-02-28T00:23:53.584608+00:00]     client: TRACE   >  EXIT: mongoc_client_start_session():1154
[localhost] < [2018-02-28T00:23:53.584634+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_assemble():704
[localhost] < [2018-02-28T00:23:53.584660+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_stream():1617
[localhost] < [2018-02-28T00:23:53.584702+00:00]    cluster: TRACE   > TRACE: mongoc_cluster_run_opmsg():2561 Function 'drop' is compressible: -1
[localhost] < [2018-02-28T00:23:53.584732+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():502
[localhost] < [2018-02-28T00:23:53.584761+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[localhost] < [2018-02-28T00:23:53.584792+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 000000C210B77480 [7]
[localhost] < [2018-02-28T00:23:53.584861+00:00]     stream: TRACE   > 00000:  65 00 00 00 02 00 00 00  00 00 00 00 dd 07 00 00  e . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:53.584926+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 50 00 00  00 02 64 72 6f 70 00 10  . . . . . P . .  . . d r o p . .
[localhost] < [2018-02-28T00:23:53.584998+00:00]     stream: TRACE   > 00020:  00 00 00 61 63 5f 6d 6f  6e 6f 6c 6f 67 5f 6c 6f  . . . a c _ m o  n o l o g _ l o
[localhost] < [2018-02-28T00:23:53.585070+00:00]     stream: TRACE   > 00030:  67 73 00 03 77 72 69 74  65 43 6f 6e 63 65 72 6e  g s . . w r i t  e C o n c e r n
[localhost] < [2018-02-28T00:23:53.585131+00:00]     stream: TRACE   > 00040:  00 0c 00 00 00 10 77 00  01 00 00 00 00 02 24 64  . . . . . . w .  . . . . . . $ d
[localhost] < [2018-02-28T00:23:53.585201+00:00]     stream: TRACE   > 00050:  62 00 0e 00 00 00 61 63  6d 6f 6e 6f 6c 6f 67 6c  b . . . . . a c  m o n o l o g l
[localhost] < [2018-02-28T00:23:53.585247+00:00]     stream: TRACE   > 00060:  6f 67 73 00 00                                    o g s . .
[localhost] < [2018-02-28T00:23:53.585275+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[localhost] < [2018-02-28T00:23:53.585301+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[localhost] < [2018-02-28T00:23:53.585327+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[localhost] < [2018-02-28T00:23:53.585356+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 000000C210BF58B0 [7]
[localhost] < [2018-02-28T00:23:53.585419+00:00]     socket: TRACE   > 00000:  65 00 00 00 02 00 00 00  00 00 00 00 dd 07 00 00  e . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:53.585482+00:00]     socket: TRACE   > 00010:  00 00 00 00 00 50 00 00  00 02 64 72 6f 70 00 10  . . . . . P . .  . . d r o p . .
[localhost] < [2018-02-28T00:23:53.585553+00:00]     socket: TRACE   > 00020:  00 00 00 61 63 5f 6d 6f  6e 6f 6c 6f 67 5f 6c 6f  . . . a c _ m o  n o l o g _ l o
[localhost] < [2018-02-28T00:23:53.585629+00:00]     socket: TRACE   > 00030:  67 73 00 03 77 72 69 74  65 43 6f 6e 63 65 72 6e  g s . . w r i t  e C o n c e r n
[localhost] < [2018-02-28T00:23:53.585689+00:00]     socket: TRACE   > 00040:  00 0c 00 00 00 10 77 00  01 00 00 00 00 02 24 64  . . . . . . w .  . . . . . . $ d
[localhost] < [2018-02-28T00:23:53.585762+00:00]     socket: TRACE   > 00050:  62 00 0e 00 00 00 61 63  6d 6f 6e 6f 6c 6f 67 6c  b . . . . . a c  m o n o l o g l
[localhost] < [2018-02-28T00:23:53.585810+00:00]     socket: TRACE   > 00060:  6f 67 73 00 00                                    o g s . .
[localhost] < [2018-02-28T00:23:53.585982+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 101 (out of: 4), ret: 0
[localhost] < [2018-02-28T00:23:53.586044+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[localhost] < [2018-02-28T00:23:53.586093+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 101 (of 4) out of iovcnt=7
[localhost] < [2018-02-28T00:23:53.586139+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 101 -= 4
[localhost] < [2018-02-28T00:23:53.586186+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 97 -= 4
[localhost] < [2018-02-28T00:23:53.586236+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 93 -= 4
[localhost] < [2018-02-28T00:23:53.586291+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 89 -= 4
[localhost] < [2018-02-28T00:23:53.586341+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 85 -= 4
[localhost] < [2018-02-28T00:23:53.586390+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 81 -= 1
[localhost] < [2018-02-28T00:23:53.586436+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 80 -= 80
[localhost] < [2018-02-28T00:23:53.586479+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[localhost] < [2018-02-28T00:23:53.586521+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[localhost] < [2018-02-28T00:23:53.586565+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 0
[localhost] < [2018-02-28T00:23:53.586607+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[localhost] < [2018-02-28T00:23:53.586648+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[localhost] < [2018-02-28T00:23:53.586692+00:00]     stream: TRACE   > TRACE: _mongoc_stream_writev_full():509 writev returned: 101
[localhost] < [2018-02-28T00:23:53.586732+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():542
[localhost] < [2018-02-28T00:23:53.586780+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[localhost] < [2018-02-28T00:23:53.586818+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[localhost] < [2018-02-28T00:23:53.586859+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[localhost] < [2018-02-28T00:23:53.586903+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[localhost] < [2018-02-28T00:23:53.586947+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[localhost] < [2018-02-28T00:23:53.587008+00:00]     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():68 setting errno: 10035 Unknown error
[localhost] < [2018-02-28T00:23:53.587058+00:00]     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():617 errno is: 10035
[localhost] < [2018-02-28T00:23:53.587105+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_wait():148
[localhost] < [2018-02-28T00:23:54.130574+00:00]     socket: TRACE   >  GOTO: mongoc_socket_recv():1074 again
[localhost] < [2018-02-28T00:23:54.130659+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[localhost] < [2018-02-28T00:23:54.130696+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[localhost] < [2018-02-28T00:23:54.130728+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000C20EB8D180 [1]
[localhost] < [2018-02-28T00:23:54.130777+00:00]     stream: TRACE   > 00000:  5d 00 00 00                                       ] . . .
[localhost] < [2018-02-28T00:23:54.130802+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[localhost] < [2018-02-28T00:23:54.130824+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[localhost] < [2018-02-28T00:23:54.130848+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[localhost] < [2018-02-28T00:23:54.130875+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[localhost] < [2018-02-28T00:23:54.130897+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[localhost] < [2018-02-28T00:23:54.130921+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[localhost] < [2018-02-28T00:23:54.130945+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[localhost] < [2018-02-28T00:23:54.130972+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[localhost] < [2018-02-28T00:23:54.131012+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[localhost] < [2018-02-28T00:23:54.131042+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[localhost] < [2018-02-28T00:23:54.131072+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000C20EB8D180 [1]
[localhost] < [2018-02-28T00:23:54.131139+00:00]     stream: TRACE   > 00000:  b5 c9 03 00 02 00 00 00  dd 07 00 00 00 00 00 00  ▒ ▒ . . . . . .  ▒ . . . . . . .
[localhost] < [2018-02-28T00:23:54.131205+00:00]     stream: TRACE   > 00010:  00 48 00 00 00 02 6e 73  00 1e 00 00 00 61 63 6d  . H . . . . n s  . . . . . a c m
[localhost] < [2018-02-28T00:23:54.131280+00:00]     stream: TRACE   > 00020:  6f 6e 6f 6c 6f 67 6c 6f  67 73 2e 61 63 5f 6d 6f  o n o l o g l o  g s . a c _ m o
[localhost] < [2018-02-28T00:23:54.131351+00:00]     stream: TRACE   > 00030:  6e 6f 6c 6f 67 5f 6c 6f  67 73 00 10 6e 49 6e 64  n o l o g _ l o  g s . . n I n d
[localhost] < [2018-02-28T00:23:54.131418+00:00]     stream: TRACE   > 00040:  65 78 65 73 57 61 73 00  07 00 00 00 01 6f 6b 00  e x e s W a s .  . . . . . o k .
[localhost] < [2018-02-28T00:23:54.131469+00:00]     stream: TRACE   > 00050:  00 00 00 00 00 00 f0 3f  00                       . . . . . . ▒ ?  .
[localhost] < [2018-02-28T00:23:54.131497+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[localhost] < [2018-02-28T00:23:54.131518+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[localhost] < [2018-02-28T00:23:54.131542+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[localhost] < [2018-02-28T00:23:54.131575+00:00]     mongoc: TRACE   > ENTRY: _mongoc_cmd_check_ok():1089
[localhost] < [2018-02-28T00:23:54.131601+00:00]     mongoc: TRACE   >  EXIT: _mongoc_cmd_check_ok():1095
[localhost] < [2018-02-28T00:23:54.131634+00:00]     client: TRACE   >  GOTO: _mongoc_client_command_with_opts():1828 done
[localhost] < [2018-02-28T00:23:54.131671+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:54.131696+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:54.131720+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_opts():1844
[localhost] < [2018-02-28T00:23:54.131786+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new_with_opts():226
[localhost] < [2018-02-28T00:23:54.131820+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[localhost] < [2018-02-28T00:23:54.131845+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():275
[localhost] < [2018-02-28T00:23:54.131874+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new_with_opts():345
[localhost] < [2018-02-28T00:23:54.131905+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_init():365
[localhost] < [2018-02-28T00:23:54.131931+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_new():37
[localhost] < [2018-02-28T00:23:54.131958+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_new():44
[localhost] < [2018-02-28T00:23:54.131983+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_init():376
[localhost] < [2018-02-28T00:23:54.134433+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[localhost] < [2018-02-28T00:23:54.134487+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[localhost] < [2018-02-28T00:23:54.134518+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[localhost] < [2018-02-28T00:23:54.134544+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[localhost] < [2018-02-28T00:23:54.134573+00:00] cursor-cursorid: TRACE   >  GOTO: _mongoc_cursor_cursorid_next():308 done
[localhost] < [2018-02-28T00:23:54.134598+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[localhost] < [2018-02-28T00:23:54.134624+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[localhost] < [2018-02-28T00:23:54.134690+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[localhost] < [2018-02-28T00:23:54.134737+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[localhost] < [2018-02-28T00:23:54.134777+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[localhost] < [2018-02-28T00:23:54.134816+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[localhost] < [2018-02-28T00:23:54.134856+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[localhost] < [2018-02-28T00:23:54.135028+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[localhost] < [2018-02-28T00:23:54.135089+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():1718
[localhost] < [2018-02-28T00:23:54.135133+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():1720
[localhost] < [2018-02-28T00:23:54.135176+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error_document():1731
[localhost] < [2018-02-28T00:23:54.135218+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error_document():1750
[localhost] < [2018-02-28T00:23:54.135256+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error_document():1772
[localhost] < [2018-02-28T00:23:54.135293+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error_document():1741
[localhost] < [2018-02-28T00:23:54.135343+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():515
[localhost] < [2018-02-28T00:23:54.135388+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_destroy():53
[localhost] < [2018-02-28T00:23:54.135453+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():532
[localhost] < [2018-02-28T00:23:54.135501+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():577
[localhost] < [2018-02-28T00:23:54.135544+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_destroy():62
[localhost] < [2018-02-28T00:23:54.135587+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():525
[localhost] < [2018-02-28T00:23:54.135794+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():798
[localhost] < [2018-02-28T00:23:54.135857+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():805
[localhost] < [2018-02-28T00:23:54.135907+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:54.135967+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:54.136012+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:54.136054+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:54.136109+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:54.136145+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:54.136187+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:54.136213+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:54.138957+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:54.139027+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:54.139073+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[localhost] < [2018-02-28T00:23:54.139101+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[localhost] < [2018-02-28T00:23:54.139168+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_opts():1724
[localhost] < [2018-02-28T00:23:54.139200+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[localhost] < [2018-02-28T00:23:54.139226+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():291
[localhost] < [2018-02-28T00:23:54.139250+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1650
[localhost] < [2018-02-28T00:23:54.139276+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1591
[localhost] < [2018-02-28T00:23:54.139304+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[localhost] < [2018-02-28T00:23:54.139337+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[localhost] < [2018-02-28T00:23:54.139362+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1617
[localhost] < [2018-02-28T00:23:54.139388+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1667
[localhost] < [2018-02-28T00:23:54.139414+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_append_opts():119
[localhost] < [2018-02-28T00:23:54.139445+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_append_opts():202
[localhost] < [2018-02-28T00:23:54.139471+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_stream():1603
[localhost] < [2018-02-28T00:23:54.139494+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_assemble():564
[localhost] < [2018-02-28T00:23:54.139530+00:00]     mongoc: TRACE   > TRACE: mongoc_cmd_parts_assemble():592 Preparing 'create'
[localhost] < [2018-02-28T00:23:54.139566+00:00]     client: TRACE   > ENTRY: mongoc_client_start_session():1150
[localhost] < [2018-02-28T00:23:54.139592+00:00]     mongoc: TRACE   > ENTRY: _mongoc_topology_pop_server_session():1288
[localhost] < [2018-02-28T00:23:54.139618+00:00]     mongoc: TRACE   >  EXIT: _mongoc_topology_pop_server_session():1314
[localhost] < [2018-02-28T00:23:54.139644+00:00]     client: TRACE   >  EXIT: mongoc_client_start_session():1154
[localhost] < [2018-02-28T00:23:54.139691+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_assemble():704
[localhost] < [2018-02-28T00:23:54.139726+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_stream():1617
[localhost] < [2018-02-28T00:23:54.139766+00:00]    cluster: TRACE   > TRACE: mongoc_cluster_run_opmsg():2561 Function 'create' is compressible: -1
[localhost] < [2018-02-28T00:23:54.139794+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():502
[localhost] < [2018-02-28T00:23:54.139819+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[localhost] < [2018-02-28T00:23:54.139850+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 000000C210B77480 [7]
[localhost] < [2018-02-28T00:23:54.139938+00:00]     stream: TRACE   > 00000:  83 00 00 00 04 00 00 00  00 00 00 00 dd 07 00 00  ▒ . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:54.140017+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 6e 00 00  00 02 63 72 65 61 74 65  . . . . . n . .  . . c r e a t e
[localhost] < [2018-02-28T00:23:54.140087+00:00]     stream: TRACE   > 00020:  00 10 00 00 00 61 63 5f  6d 6f 6e 6f 6c 6f 67 5f  . . . . . a c _  m o n o l o g _
[localhost] < [2018-02-28T00:23:54.140156+00:00]     stream: TRACE   > 00030:  6c 6f 67 73 00 08 63 61  70 70 65 64 00 01 10 6d  l o g s . . c a  p p e d . . . m
[localhost] < [2018-02-28T00:23:54.140258+00:00]     stream: TRACE   > 00040:  61 78 00 c0 c6 2d 00 10  73 69 7a 65 00 00 00 00  a x . ▒ ▒ - . .  s i z e . . . .
[localhost] < [2018-02-28T00:23:54.140364+00:00]     stream: TRACE   > 00050:  40 03 77 72 69 74 65 43  6f 6e 63 65 72 6e 00 0c  @ . w r i t e C  o n c e r n . .
[localhost] < [2018-02-28T00:23:54.140429+00:00]     stream: TRACE   > 00060:  00 00 00 10 77 00 01 00  00 00 00 02 24 64 62 00  . . . . w . . .  . . . . $ d b .
[localhost] < [2018-02-28T00:23:54.140499+00:00]     stream: TRACE   > 00070:  0e 00 00 00 61 63 6d 6f  6e 6f 6c 6f 67 6c 6f 67  . . . . a c m o  n o l o g l o g
[localhost] < [2018-02-28T00:23:54.140539+00:00]     stream: TRACE   > 00080:  73 00 00                                          s . .
[localhost] < [2018-02-28T00:23:54.140568+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[localhost] < [2018-02-28T00:23:54.140594+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[localhost] < [2018-02-28T00:23:54.140620+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[localhost] < [2018-02-28T00:23:54.140652+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 000000C210BF6030 [7]
[localhost] < [2018-02-28T00:23:54.140756+00:00]     socket: TRACE   > 00000:  83 00 00 00 04 00 00 00  00 00 00 00 dd 07 00 00  ▒ . . . . . . .  . . . . ▒ . . .
[localhost] < [2018-02-28T00:23:54.140824+00:00]     socket: TRACE   > 00010:  00 00 00 00 00 6e 00 00  00 02 63 72 65 61 74 65  . . . . . n . .  . . c r e a t e
[localhost] < [2018-02-28T00:23:54.140894+00:00]     socket: TRACE   > 00020:  00 10 00 00 00 61 63 5f  6d 6f 6e 6f 6c 6f 67 5f  . . . . . a c _  m o n o l o g _
[localhost] < [2018-02-28T00:23:54.140964+00:00]     socket: TRACE   > 00030:  6c 6f 67 73 00 08 63 61  70 70 65 64 00 01 10 6d  l o g s . . c a  p p e d . . . m
[localhost] < [2018-02-28T00:23:54.141042+00:00]     socket: TRACE   > 00040:  61 78 00 c0 c6 2d 00 10  73 69 7a 65 00 00 00 00  a x . ▒ ▒ - . .  s i z e . . . .
[localhost] < [2018-02-28T00:23:54.141162+00:00]     socket: TRACE   > 00050:  40 03 77 72 69 74 65 43  6f 6e 63 65 72 6e 00 0c  @ . w r i t e C  o n c e r n . .
[localhost] < [2018-02-28T00:23:54.141264+00:00]     socket: TRACE   > 00060:  00 00 00 10 77 00 01 00  00 00 00 02 24 64 62 00  . . . . w . . .  . . . . $ d b .
[localhost] < [2018-02-28T00:23:54.141380+00:00]     socket: TRACE   > 00070:  0e 00 00 00 61 63 6d 6f  6e 6f 6c 6f 67 6c 6f 67  . . . . a c m o  n o l o g l o g
[localhost] < [2018-02-28T00:23:54.141449+00:00]     socket: TRACE   > 00080:  73 00 00                                          s . .
[localhost] < [2018-02-28T00:23:54.141681+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 131 (out of: 4), ret: 0
[localhost] < [2018-02-28T00:23:54.141746+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[localhost] < [2018-02-28T00:23:54.141793+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 131 (of 4) out of iovcnt=7
[.......]
  • the db.printCollectionStats() return with the collection that raise the error:
ac_monolog_logs
{
	"ns" : "acmonologlogs.ac_monolog_logs",
	"size" : 3644678,
	"count" : 6216,
	"avgObjSize" : 586,
	"storageSize" : 901120,
	"capped" : false,
	"wiredTiger" : {
		"metadata" : {
			"formatVersion" : 1
		},
		"creationString" : "access_pattern_hint=none,allocation_size=4KB,app_metadata=(formatVersion=1),assert=(commit_timestamp=none,read_timestamp=none),block_allocation=best,block_compressor=snappy,cache_resident=false,checksum=on,colgroups=,collator=,columns=,dictionary=0,encryption=(keyid=,name=),exclusive=false,extractor=,format=btree,huffman_key=,huffman_value=,ignore_in_memory_cache_size=false,immutable=false,internal_item_max=0,internal_key_max=0,internal_key_truncate=true,internal_page_max=4KB,key_format=q,key_gap=10,leaf_item_max=0,leaf_key_max=0,leaf_page_max=32KB,leaf_value_max=64MB,log=(enabled=true),lsm=(auto_throttle=true,bloom=true,bloom_bit_count=16,bloom_config=,bloom_hash_count=8,bloom_oldest=false,chunk_count_limit=0,chunk_max=5GB,chunk_size=10MB,merge_max=15,merge_min=0),memory_page_max=10m,os_cache_dirty_max=0,os_cache_max=0,prefix_compression=false,prefix_compression_min=4,source=,split_deepen_min_child=0,split_deepen_per_child=0,split_pct=90,type=file,value_format=u",
		"type" : "file",
		"uri" : "statistics:table:collection-116--6203147886901550772",
		"LSM" : {
			"bloom filter false positives" : 0,
			"bloom filter hits" : 0,
			"bloom filter misses" : 0,
			"bloom filter pages evicted from cache" : 0,
			"bloom filter pages read into cache" : 0,
			"bloom filters in the LSM tree" : 0,
			"chunks in the LSM tree" : 0,
			"highest merge generation in the LSM tree" : 0,
			"queries that could have benefited from a Bloom filter that did not exist" : 0,
			"sleep for LSM checkpoint throttle" : 0,
			"sleep for LSM merge throttle" : 0,
			"total size of bloom filters" : 0
		},
		"block-manager" : {
			"allocations requiring file extension" : 490,
			"blocks allocated" : 1636,
			"blocks freed" : 839,
			"checkpoint size" : 864256,
			"file allocation unit size" : 4096,
			"file bytes available for reuse" : 20480,
			"file magic number" : 120897,
			"file major version number" : 1,
			"file size in bytes" : 901120,
			"minor version number" : 0
		},
		"btree" : {
			"btree checkpoint generation" : 1884,
			"column-store fixed-size leaf pages" : 0,
			"column-store internal pages" : 0,
			"column-store variable-size RLE encoded values" : 0,
			"column-store variable-size deleted values" : 0,
			"column-store variable-size leaf pages" : 0,
			"fixed-record size" : 0,
			"maximum internal page key size" : 368,
			"maximum internal page size" : 4096,
			"maximum leaf page key size" : 2867,
			"maximum leaf page size" : 32768,
			"maximum leaf page value size" : 67108864,
			"maximum tree depth" : 3,
			"number of key/value pairs" : 0,
			"overflow pages" : 0,
			"pages rewritten by compaction" : 0,
			"row-store internal pages" : 0,
			"row-store leaf pages" : 0
		},
		"cache" : {
			"bytes currently in the cache" : 4445128,
			"bytes read into cache" : 4475175,
			"bytes written from cache" : 20571821,
			"checkpoint blocked page eviction" : 0,
			"data source pages selected for eviction unable to be evicted" : 0,
			"eviction walk passes of a file" : 0,
			"eviction walk target pages histogram - 0-9" : 0,
			"eviction walk target pages histogram - 10-31" : 0,
			"eviction walk target pages histogram - 128 and higher" : 0,
			"eviction walk target pages histogram - 32-63" : 0,
			"eviction walk target pages histogram - 64-128" : 0,
			"eviction walks abandoned" : 0,
			"eviction walks gave up because they restarted their walk twice" : 0,
			"eviction walks gave up because they saw too many pages and found no candidates" : 0,
			"eviction walks gave up because they saw too many pages and found too few candidates" : 0,
			"eviction walks reached end of tree" : 0,
			"eviction walks started from root of tree" : 0,
			"eviction walks started from saved location in tree" : 0,
			"hazard pointer blocked page eviction" : 0,
			"in-memory page passed criteria to be split" : 0,
			"in-memory page splits" : 0,
			"internal pages evicted" : 0,
			"internal pages split during eviction" : 0,
			"leaf pages split during eviction" : 0,
			"modified pages evicted" : 161,
			"overflow pages read into cache" : 0,
			"page split during eviction deepened the tree" : 0,
			"page written requiring lookaside records" : 0,
			"pages read into cache" : 160,
			"pages read into cache requiring lookaside entries" : 0,
			"pages requested from the cache" : 492464,
			"pages seen by eviction walk" : 0,
			"pages written from cache" : 1086,
			"pages written requiring in-memory restoration" : 0,
			"tracked dirty bytes in the cache" : 0,
			"unmodified pages evicted" : 0
		},
		"cache_walk" : {
			"Average difference between current eviction generation when the page was last considered" : 0,
			"Average on-disk page image size seen" : 0,
			"Average time in cache for pages that have been visited by the eviction server" : 0,
			"Average time in cache for pages that have not been visited by the eviction server" : 0,
			"Clean pages currently in cache" : 0,
			"Current eviction generation" : 0,
			"Dirty pages currently in cache" : 0,
			"Entries in the root page" : 0,
			"Internal pages currently in cache" : 0,
			"Leaf pages currently in cache" : 0,
			"Maximum difference between current eviction generation when the page was last considered" : 0,
			"Maximum page size seen" : 0,
			"Minimum on-disk page image size seen" : 0,
			"Number of pages never visited by eviction server" : 0,
			"On-disk page image sizes smaller than a single allocation unit" : 0,
			"Pages created in memory and never written" : 0,
			"Pages currently queued for eviction" : 0,
			"Pages that could not be queued for eviction" : 0,
			"Refs skipped during cache traversal" : 0,
			"Size of the root page" : 0,
			"Total number of pages currently in cache" : 0
		},
		"compression" : {
			"compressed pages read" : 159,
			"compressed pages written" : 805,
			"page written failed to compress" : 0,
			"page written was too small to compress" : 281,
			"raw compression call failed, additional data available" : 0,
			"raw compression call failed, no additional data available" : 0,
			"raw compression call succeeded" : 0
		},
		"cursor" : {
			"bulk-loaded cursor-insert calls" : 0,
			"create calls" : 56,
			"cursor-insert key and value bytes inserted" : 12503423,
			"cursor-remove key bytes removed" : 60699,
			"cursor-update value bytes updated" : 0,
			"insert calls" : 21463,
			"modify calls" : 0,
			"next calls" : 50673756,
			"prev calls" : 7,
			"remove calls" : 22591,
			"reserve calls" : 0,
			"reset calls" : 492114,
			"restarted searches" : 30,
			"search calls" : 45182,
			"search near calls" : 413213,
			"truncate calls" : 0,
			"update calls" : 0
		},
		"reconciliation" : {
			"dictionary matches" : 0,
			"fast-path pages deleted" : 0,
			"internal page key bytes discarded using suffix compression" : 41033,
			"internal page multi-block writes" : 0,
			"internal-page overflow keys" : 0,
			"leaf page key bytes discarded using prefix compression" : 0,
			"leaf page multi-block writes" : 264,
			"leaf-page overflow keys" : 0,
			"maximum blocks required for a page" : 1,
			"overflow values written" : 0,
			"page checksum matches" : 19816,
			"page reconciliation calls" : 709,
			"page reconciliation calls for eviction" : 161,
			"pages deleted" : 158
		},
		"session" : {
			"object compaction" : 0,
			"open cursor count" : 3
		},
		"transaction" : {
			"update conflicts" : 0
		}
	},
	"nindexes" : 1,
	"totalIndexSize" : 118784,
	"indexSizes" : {
		"_id_" : 118784
	},
	"ok" : 1
}
---

@jmikola
Copy link
Member

jmikola commented Feb 28, 2018

According to printCollectionStats(), the acmonologlogs.ac_monolog_logs collection is not capped.

From the mongodb.debug trace logs, we see following commands run:

  • isMaster to discover the standalone server
  • drop the ac_monolog_logs collection
  • create the ac_monolog_logs collection (with capped, max, and size options)

The trace cuts off before we see the response to the create command.

I have no idea what bin/console ac:monolog:create --env=prod is. I found no record of any collection management in the monolog repository. There is only a handler class responsible for inserting log entries. Assuming this is your custom console command alluded to in #1745 (comment), the trace logs we see (drop followed by create) doesn't agree with the source you shared above.

Thinking ahead, it seems possible that you may be trying to manage the schema of this log collection from within the same app that is actively logging while doing so. If so, I'd suggest doing this outside of the application (e.g. use the MongoDB shell) or ensure that the console command in question disables logging completely. Considering Monolog uses the extension/library directly to insert log messages, mapping them in ODM sounds like over-architecting.

@acrozes
Copy link
Author

acrozes commented Mar 1, 2018

The logs until the error:


[2018-02-28T02:32:05.621268+00:00]     PHONGO: DEBUG   > Connection string: 'mongodb://127.0.0.1:27017'
[2018-02-28T02:32:05.621339+00:00]     PHONGO: DEBUG   > Creating Manager, phongo-1.4.1[stable] - mongoc-1.9.2(bundled), libbson-1.9.2(bundled), php-7.2.1-dev
[2018-02-28T02:32:05.621386+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_init():75
[2018-02-28T02:32:05.630186+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_init():94
[2018-02-28T02:32:05.630310+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_init():104
[2018-02-28T02:32:05.630349+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_init():123
[2018-02-28T02:32:05.630407+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_init():1867
[2018-02-28T02:32:05.630446+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_init():1894
[2018-02-28T02:32:05.630483+00:00]     PHONGO: DEBUG   > Created client hash: a:4:{s:3:"pid";i:4128;s:3:"uri";s:25:"mongodb://127.0.0.1:27017";s:7:"options";a:0:{}s:13:"driverOptions";a:0:{}}

[2018-02-28T02:32:05.649817+00:00] topology_scanner: TRACE   > ENTRY: mongoc_topology_scanner_node_connect_tcp():468
[2018-02-28T02:32:05.649908+00:00]     socket: TRACE   > ENTRY: mongoc_socket_new():977
[2018-02-28T02:32:05.650388+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_setnodelay():556
[2018-02-28T02:32:05.650448+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_setnodelay():568
[2018-02-28T02:32:05.650470+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_setkeepalive():521
[2018-02-28T02:32:05.650503+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive():525 Setting SO_KEEPALIVE
[2018-02-28T02:32:05.650671+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():420 KeepAlive values updated
[2018-02-28T02:32:05.650721+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():421 KeepAliveTime: 300000
[2018-02-28T02:32:05.650758+00:00]     socket: TRACE   > TRACE: _mongoc_socket_setkeepalive_windows():422 KeepAliveInterval: 1000
[2018-02-28T02:32:05.650794+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_setkeepalive():537
[2018-02-28T02:32:05.650830+00:00]     socket: TRACE   >  EXIT: mongoc_socket_new():1009
[2018-02-28T02:32:05.650866+00:00]     socket: TRACE   > ENTRY: mongoc_socket_connect():840
[2018-02-28T02:32:05.651586+00:00]     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():68 setting errno: 10035 Unknown error
[2018-02-28T02:32:05.651680+00:00]     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():617 errno is: 10035
[2018-02-28T02:32:05.651747+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_wait():148
[2018-02-28T02:32:05.651868+00:00]     socket: TRACE   >  EXIT: mongoc_socket_connect():865
[2018-02-28T02:32:05.651987+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_poll():223
[2018-02-28T02:32:05.652027+00:00]     socket: TRACE   > ENTRY: mongoc_socket_poll():283
[2018-02-28T02:32:05.652081+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_poll():249
[2018-02-28T02:32:05.652131+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[2018-02-28T02:32:05.652177+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 0000000752C2BD50 [9]
[2018-02-28T02:32:05.652299+00:00]     stream: TRACE   > 00000:  50 01 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  P . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.652428+00:00]     stream: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
[2018-02-28T02:32:05.652547+00:00]     stream: TRACE   > 00020:  00 00 00 ff ff ff ff 29  01 00 00 10 69 73 4d 61  . . . . . . . )  . . . . i s M a
[2018-02-28T02:32:05.652657+00:00]     stream: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 03 63 6c 69 65 6e 74  s t e r . . . .  . . c l i e n t
[2018-02-28T02:32:05.652771+00:00]     stream: TRACE   > 00040:  00 fc 00 00 00 03 64 72  69 76 65 72 00 43 00 00  . . . . . . d r  i v e r . C . .
[2018-02-28T02:32:05.652880+00:00]     stream: TRACE   > 00050:  00 02 6e 61 6d 65 00 19  00 00 00 6d 6f 6e 67 6f  . . n a m e . .  . . . m o n g o
[2018-02-28T02:32:05.653013+00:00]     stream: TRACE   > 00060:  63 20 2f 20 65 78 74 2d  6d 6f 6e 67 6f 64 62 3a  c   /   e x t -  m o n g o d b :
[2018-02-28T02:32:05.653131+00:00]     stream: TRACE   > 00070:  50 48 50 00 02 76 65 72  73 69 6f 6e 00 0e 00 00  P H P . . v e r  s i o n . . . .
[2018-02-28T02:32:05.653265+00:00]     stream: TRACE   > 00080:  00 31 2e 39 2e 32 20 2f  20 31 2e 34 2e 31 00 00  . 1 . 9 . 2   /    1 . 4 . 1 . .
[2018-02-28T02:32:05.653385+00:00]     stream: TRACE   > 00090:  03 6f 73 00 5a 00 00 00  02 74 79 70 65 00 08 00  . o s . Z . . .  . t y p e . . .
[2018-02-28T02:32:05.653516+00:00]     stream: TRACE   > 000a0:  00 00 57 69 6e 64 6f 77  73 00 02 6e 61 6d 65 00  . . W i n d o w  s . . n a m e .
[2018-02-28T02:32:05.653642+00:00]     stream: TRACE   > 000b0:  08 00 00 00 57 69 6e 64  6f 77 73 00 02 76 65 72  . . . . W i n d  o w s . . v e r
[2018-02-28T02:32:05.653767+00:00]     stream: TRACE   > 000c0:  73 69 6f 6e 00 0b 00 00  00 36 2e 33 20 28 39 36  s i o n . . . .  . 6 . 3   ( 9 6
[2018-02-28T02:32:05.653911+00:00]     stream: TRACE   > 000d0:  30 30 29 00 02 61 72 63  68 69 74 65 63 74 75 72  0 0 ) . . a r c  h i t e c t u r
[2018-02-28T02:32:05.654032+00:00]     stream: TRACE   > 000e0:  65 00 07 00 00 00 78 38  36 5f 36 34 00 00 02 70  e . . . . . x 8  6 _ 6 4 . . . p
[2018-02-28T02:32:05.654159+00:00]     stream: TRACE   > 000f0:  6c 61 74 66 6f 72 6d 00  40 00 00 00 63 66 67 3d  l a t f o r m .  @ . . . c f g =
[2018-02-28T02:32:05.654293+00:00]     stream: TRACE   > 00100:  30 78 34 30 32 61 30 65  39 20 43 43 3d 4d 53 56  0 x 4 0 2 a 0 e  9   C C = M S V
[2018-02-28T02:32:05.654425+00:00]     stream: TRACE   > 00110:  43 20 31 39 31 32 20 43  46 4c 41 47 53 3d 22 22  C   1 9 1 2   C  F L A G S = " "
[2018-02-28T02:32:05.654562+00:00]     stream: TRACE   > 00120:  20 4c 44 46 4c 41 47 53  3d 22 22 20 2f 20 50 48    L D F L A G S  = " "   /   P H
[2018-02-28T02:32:05.654693+00:00]     stream: TRACE   > 00130:  50 20 37 2e 32 2e 31 2d  64 65 76 00 00 04 63 6f  P   7 . 2 . 1 -  d e v . . . c o
[2018-02-28T02:32:05.654816+00:00]     stream: TRACE   > 00140:  6d 70 72 65 73 73 69 6f  6e 00 05 00 00 00 00 00  m p r e s s i o  n . . . . . . .
[2018-02-28T02:32:05.654868+00:00]     stream: TRACE   >
[2018-02-28T02:32:05.654912+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[2018-02-28T02:32:05.654953+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[2018-02-28T02:32:05.654994+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[2018-02-28T02:32:05.655039+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 0000000752C13190 [9]
[2018-02-28T02:32:05.655146+00:00]     socket: TRACE   > 00000:  50 01 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  P . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.655273+00:00]     socket: TRACE   > 00010:  04 00 00 00 61 64 6d 69  6e 2e 24 63 6d 64 00 00  . . . . a d m i  n . $ c m d . .
[2018-02-28T02:32:05.655390+00:00]     socket: TRACE   > 00020:  00 00 00 ff ff ff ff 29  01 00 00 10 69 73 4d 61  . . . . . . . )  . . . . i s M a
[2018-02-28T02:32:05.655515+00:00]     socket: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 03 63 6c 69 65 6e 74  s t e r . . . .  . . c l i e n t
[2018-02-28T02:32:05.655639+00:00]     socket: TRACE   > 00040:  00 fc 00 00 00 03 64 72  69 76 65 72 00 43 00 00  . . . . . . d r  i v e r . C . .
[2018-02-28T02:32:05.655764+00:00]     socket: TRACE   > 00050:  00 02 6e 61 6d 65 00 19  00 00 00 6d 6f 6e 67 6f  . . n a m e . .  . . . m o n g o
[2018-02-28T02:32:05.655902+00:00]     socket: TRACE   > 00060:  63 20 2f 20 65 78 74 2d  6d 6f 6e 67 6f 64 62 3a  c   /   e x t -  m o n g o d b :
[2018-02-28T02:32:05.656027+00:00]     socket: TRACE   > 00070:  50 48 50 00 02 76 65 72  73 69 6f 6e 00 0e 00 00  P H P . . v e r  s i o n . . . .
[2018-02-28T02:32:05.656160+00:00]     socket: TRACE   > 00080:  00 31 2e 39 2e 32 20 2f  20 31 2e 34 2e 31 00 00  . 1 . 9 . 2   /    1 . 4 . 1 . .
[2018-02-28T02:32:05.656279+00:00]     socket: TRACE   > 00090:  03 6f 73 00 5a 00 00 00  02 74 79 70 65 00 08 00  . o s . Z . . .  . t y p e . . .
[2018-02-28T02:32:05.656406+00:00]     socket: TRACE   > 000a0:  00 00 57 69 6e 64 6f 77  73 00 02 6e 61 6d 65 00  . . W i n d o w  s . . n a m e .
[2018-02-28T02:32:05.656533+00:00]     socket: TRACE   > 000b0:  08 00 00 00 57 69 6e 64  6f 77 73 00 02 76 65 72  . . . . W i n d  o w s . . v e r
[2018-02-28T02:32:05.656665+00:00]     socket: TRACE   > 000c0:  73 69 6f 6e 00 0b 00 00  00 36 2e 33 20 28 39 36  s i o n . . . .  . 6 . 3   ( 9 6
[2018-02-28T02:32:05.656776+00:00]     socket: TRACE   > 000d0:  30 30 29 00 02 61 72 63  68 69 74 65 63 74 75 72  0 0 ) . . a r c  h i t e c t u r
[2018-02-28T02:32:05.656857+00:00]     socket: TRACE   > 000e0:  65 00 07 00 00 00 78 38  36 5f 36 34 00 00 02 70  e . . . . . x 8  6 _ 6 4 . . . p
[2018-02-28T02:32:05.656944+00:00]     socket: TRACE   > 000f0:  6c 61 74 66 6f 72 6d 00  40 00 00 00 63 66 67 3d  l a t f o r m .  @ . . . c f g =
[2018-02-28T02:32:05.657037+00:00]     socket: TRACE   > 00100:  30 78 34 30 32 61 30 65  39 20 43 43 3d 4d 53 56  0 x 4 0 2 a 0 e  9   C C = M S V
[2018-02-28T02:32:05.657126+00:00]     socket: TRACE   > 00110:  43 20 31 39 31 32 20 43  46 4c 41 47 53 3d 22 22  C   1 9 1 2   C  F L A G S = " "
[2018-02-28T02:32:05.657265+00:00]     socket: TRACE   > 00120:  20 4c 44 46 4c 41 47 53  3d 22 22 20 2f 20 50 48    L D F L A G S  = " "   /   P H
[2018-02-28T02:32:05.657922+00:00]     socket: TRACE   > 00130:  50 20 37 2e 32 2e 31 2d  64 65 76 00 00 04 63 6f  P   7 . 2 . 1 -  d e v . . . c o
[2018-02-28T02:32:05.658112+00:00]     socket: TRACE   > 00140:  6d 70 72 65 73 73 69 6f  6e 00 05 00 00 00 00 00  m p r e s s i o  n . . . . . . .
[2018-02-28T02:32:05.658247+00:00]     socket: TRACE   >
[2018-02-28T02:32:05.658971+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 336 (out of: 4), ret: 0
[2018-02-28T02:32:05.659413+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[2018-02-28T02:32:05.659542+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 336 (of 4) out of iovcnt=9
[2018-02-28T02:32:05.659590+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 336 -= 4
[2018-02-28T02:32:05.659633+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 332 -= 4
[2018-02-28T02:32:05.659677+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 328 -= 4
[2018-02-28T02:32:05.659716+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 324 -= 4
[2018-02-28T02:32:05.659754+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 320 -= 4
[2018-02-28T02:32:05.659794+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 316 -= 11
[2018-02-28T02:32:05.659832+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 305 -= 4
[2018-02-28T02:32:05.659871+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 301 -= 4
[2018-02-28T02:32:05.659910+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 297 -= 297
[2018-02-28T02:32:05.659947+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[2018-02-28T02:32:05.659988+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[2018-02-28T02:32:05.660029+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 10035
[2018-02-28T02:32:05.660062+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[2018-02-28T02:32:05.660099+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[2018-02-28T02:32:05.660139+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_poll():223
[2018-02-28T02:32:05.660170+00:00]     socket: TRACE   > ENTRY: mongoc_socket_poll():283
[2018-02-28T02:32:05.660229+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_poll():249
[2018-02-28T02:32:05.660279+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():336
[2018-02-28T02:32:05.660305+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.660339+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.660371+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.660405+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.660451+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.660485+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.660526+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066DAC0 [1]
[2018-02-28T02:32:05.660599+00:00]     stream: TRACE   > 00000:  cd 00 00 00                                       . . . .
[2018-02-28T02:32:05.660628+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.660659+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.660692+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():368
[2018-02-28T02:32:05.660725+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():336
[2018-02-28T02:32:05.660753+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.660788+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.660822+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.660857+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.660900+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.660933+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.660977+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066DAC0 [1]
[2018-02-28T02:32:05.661061+00:00]     stream: TRACE   > 00000:  bc cf 03 00 01 00 00 00  01 00 00 00 08 00 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.661136+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 00 00 00  00 00 00 00 01 00 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.661224+00:00]     stream: TRACE   > 00020:  a9 00 00 00 08 69 73 6d  61 73 74 65 72 00 01 10  . . . . . i s m  a s t e r . . .
[2018-02-28T02:32:05.661316+00:00]     stream: TRACE   > 00030:  6d 61 78 42 73 6f 6e 4f  62 6a 65 63 74 53 69 7a  m a x B s o n O  b j e c t S i z
[2018-02-28T02:32:05.661400+00:00]     stream: TRACE   > 00040:  65 00 00 00 00 01 10 6d  61 78 4d 65 73 73 61 67  e . . . . . . m  a x M e s s a g
[2018-02-28T02:32:05.661493+00:00]     stream: TRACE   > 00050:  65 53 69 7a 65 42 79 74  65 73 00 00 6c dc 02 10  e S i z e B y t  e s . . l . . .
[2018-02-28T02:32:05.661683+00:00]     stream: TRACE   > 00060:  6d 61 78 57 72 69 74 65  42 61 74 63 68 53 69 7a  m a x W r i t e  B a t c h S i z
[2018-02-28T02:32:05.661836+00:00]     stream: TRACE   > 00070:  65 00 a0 86 01 00 09 6c  6f 63 61 6c 54 69 6d 65  e . . . . . . l  o c a l T i m e
[2018-02-28T02:32:05.661966+00:00]     stream: TRACE   > 00080:  00 1b a7 40 da 61 01 00  00 10 6d 69 6e 57 69 72  . . . @ . a . .  . . m i n W i r
[2018-02-28T02:32:05.662093+00:00]     stream: TRACE   > 00090:  65 56 65 72 73 69 6f 6e  00 00 00 00 00 10 6d 61  e V e r s i o n  . . . . . . m a
[2018-02-28T02:32:05.662224+00:00]     stream: TRACE   > 000a0:  78 57 69 72 65 56 65 72  73 69 6f 6e 00 06 00 00  x W i r e V e r  s i o n . . . .
[2018-02-28T02:32:05.662349+00:00]     stream: TRACE   > 000b0:  00 08 72 65 61 64 4f 6e  6c 79 00 00 01 6f 6b 00  . . r e a d O n  l y . . . o k .
[2018-02-28T02:32:05.662459+00:00]     stream: TRACE   > 000c0:  00 00 00 00 00 00 f0 3f  00                       . . . . . . . ?  .
[2018-02-28T02:32:05.662506+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.662564+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.662613+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():368
[2018-02-28T02:32:05.662683+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.662743+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.662804+00:00]     mongoc: TRACE   > TRACE: mongoc_topology_description_handle_ismaster():1955 No transition entry to Single for Standalone
[2018-02-28T02:32:05.662866+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():798
[2018-02-28T02:32:05.662906+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():805
[2018-02-28T02:32:05.662955+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.663007+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.663047+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.663088+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.663158+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.663214+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.663275+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.663315+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.663417+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_opts():1724
[2018-02-28T02:32:05.663473+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[2018-02-28T02:32:05.663513+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():291
[2018-02-28T02:32:05.663567+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1650
[2018-02-28T02:32:05.663651+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1591
[2018-02-28T02:32:05.663713+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.663767+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.663820+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1617
[2018-02-28T02:32:05.663861+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1667
[2018-02-28T02:32:05.663911+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_append_opts():119
[2018-02-28T02:32:05.663953+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_append_opts():202
[2018-02-28T02:32:05.664000+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_stream():1603
[2018-02-28T02:32:05.664041+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_assemble():564
[2018-02-28T02:32:05.664084+00:00]     mongoc: TRACE   > TRACE: mongoc_cmd_parts_assemble():592 Preparing 'listCollections'
[2018-02-28T02:32:05.664153+00:00]     client: TRACE   > ENTRY: mongoc_client_start_session():1150
[2018-02-28T02:32:05.664193+00:00]     mongoc: TRACE   > ENTRY: _mongoc_topology_pop_server_session():1288
[2018-02-28T02:32:05.664244+00:00]     mongoc: TRACE   >  EXIT: _mongoc_topology_pop_server_session():1314
[2018-02-28T02:32:05.664292+00:00]     client: TRACE   >  EXIT: mongoc_client_start_session():1154
[2018-02-28T02:32:05.664331+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_assemble():704
[2018-02-28T02:32:05.664370+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_stream():1617
[2018-02-28T02:32:05.664443+00:00]    cluster: TRACE   > TRACE: mongoc_cluster_run_opmsg():2561 Function 'listCollections' is compressible: -1
[2018-02-28T02:32:05.664486+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():502
[2018-02-28T02:32:05.664526+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[2018-02-28T02:32:05.664576+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 0000000752C25940 [7]
[2018-02-28T02:32:05.664697+00:00]     stream: TRACE   > 00000:  77 00 00 00 02 00 00 00  00 00 00 00 dd 07 00 00  w . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.664826+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 62 00 00  00 10 6c 69 73 74 43 6f  . . . . . b . .  . . l i s t C o
[2018-02-28T02:32:05.664950+00:00]     stream: TRACE   > 00020:  6c 6c 65 63 74 69 6f 6e  73 00 01 00 00 00 02 24  l l e c t i o n  s . . . . . . $
[2018-02-28T02:32:05.665099+00:00]     stream: TRACE   > 00030:  64 62 00 0e 00 00 00 61  63 6d 6f 6e 6f 6c 6f 67  d b . . . . . a  c m o n o l o g
[2018-02-28T02:32:05.665232+00:00]     stream: TRACE   > 00040:  6c 6f 67 73 00 03 24 72  65 61 64 50 72 65 66 65  l o g s . . $ r  e a d P r e f e
[2018-02-28T02:32:05.665361+00:00]     stream: TRACE   > 00050:  72 65 6e 63 65 00 20 00  00 00 02 6d 6f 64 65 00  r e n c e .   .  . . . m o d e .
[2018-02-28T02:32:05.665493+00:00]     stream: TRACE   > 00060:  11 00 00 00 70 72 69 6d  61 72 79 50 72 65 66 65  . . . . p r i m  a r y P r e f e
[2018-02-28T02:32:05.665679+00:00]     stream: TRACE   > 00070:  72 72 65 64 00 00 00                              r r e d . . .
[2018-02-28T02:32:05.665761+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[2018-02-28T02:32:05.665874+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[2018-02-28T02:32:05.665920+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[2018-02-28T02:32:05.665967+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 00000007526E8FC0 [7]
[2018-02-28T02:32:05.666079+00:00]     socket: TRACE   > 00000:  77 00 00 00 02 00 00 00  00 00 00 00 dd 07 00 00  w . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.666205+00:00]     socket: TRACE   > 00010:  00 00 00 00 00 62 00 00  00 10 6c 69 73 74 43 6f  . . . . . b . .  . . l i s t C o
[2018-02-28T02:32:05.666333+00:00]     socket: TRACE   > 00020:  6c 6c 65 63 74 69 6f 6e  73 00 01 00 00 00 02 24  l l e c t i o n  s . . . . . . $
[2018-02-28T02:32:05.666468+00:00]     socket: TRACE   > 00030:  64 62 00 0e 00 00 00 61  63 6d 6f 6e 6f 6c 6f 67  d b . . . . . a  c m o n o l o g
[2018-02-28T02:32:05.666603+00:00]     socket: TRACE   > 00040:  6c 6f 67 73 00 03 24 72  65 61 64 50 72 65 66 65  l o g s . . $ r  e a d P r e f e
[2018-02-28T02:32:05.666726+00:00]     socket: TRACE   > 00050:  72 65 6e 63 65 00 20 00  00 00 02 6d 6f 64 65 00  r e n c e .   .  . . . m o d e .
[2018-02-28T02:32:05.666853+00:00]     socket: TRACE   > 00060:  11 00 00 00 70 72 69 6d  61 72 79 50 72 65 66 65  . . . . p r i m  a r y P r e f e
[2018-02-28T02:32:05.666935+00:00]     socket: TRACE   > 00070:  72 72 65 64 00 00 00                              r r e d . . .
[2018-02-28T02:32:05.667138+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 119 (out of: 4), ret: 0
[2018-02-28T02:32:05.667189+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[2018-02-28T02:32:05.667235+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 119 (of 4) out of iovcnt=7
[2018-02-28T02:32:05.667285+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 119 -= 4
[2018-02-28T02:32:05.667333+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 115 -= 4
[2018-02-28T02:32:05.667379+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 111 -= 4
[2018-02-28T02:32:05.667428+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 107 -= 4
[2018-02-28T02:32:05.667472+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 103 -= 4
[2018-02-28T02:32:05.667517+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 99 -= 1
[2018-02-28T02:32:05.667567+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 98 -= 98
[2018-02-28T02:32:05.667652+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[2018-02-28T02:32:05.667700+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[2018-02-28T02:32:05.667743+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 0
[2018-02-28T02:32:05.667782+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[2018-02-28T02:32:05.667820+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[2018-02-28T02:32:05.667862+00:00]     stream: TRACE   > TRACE: _mongoc_stream_writev_full():509 writev returned: 119
[2018-02-28T02:32:05.667899+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():542
[2018-02-28T02:32:05.667938+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:05.667973+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.668012+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.668047+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.668088+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.668139+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.668180+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.668224+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D1A0 [1]
[2018-02-28T02:32:05.668298+00:00]     stream: TRACE   > 00000:  53 01 00 00                                       S . . .
[2018-02-28T02:32:05.668344+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.668374+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.668416+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:05.668456+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:05.668493+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.668526+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.668569+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.668607+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.668652+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.668692+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.668735+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D1A0 [1]
[2018-02-28T02:32:05.668846+00:00]     stream: TRACE   > 00000:  bd cf 03 00 02 00 00 00  dd 07 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.668970+00:00]     stream: TRACE   > 00010:  00 3e 01 00 00 03 63 75  72 73 6f 72 00 25 01 00  . > . . . . c u  r s o r . % . .
[2018-02-28T02:32:05.669086+00:00]     stream: TRACE   > 00020:  00 12 69 64 00 00 00 00  00 00 00 00 00 02 6e 73  . . i d . . . .  . . . . . . n s
[2018-02-28T02:32:05.669215+00:00]     stream: TRACE   > 00030:  00 23 00 00 00 61 63 6d  6f 6e 6f 6c 6f 67 6c 6f  . # . . . a c m  o n o l o g l o
[2018-02-28T02:32:05.669355+00:00]     stream: TRACE   > 00040:  67 73 2e 24 63 6d 64 2e  6c 69 73 74 43 6f 6c 6c  g s . $ c m d .  l i s t C o l l
[2018-02-28T02:32:05.669490+00:00]     stream: TRACE   > 00050:  65 63 74 69 6f 6e 73 00  04 66 69 72 73 74 42 61  e c t i o n s .  . f i r s t B a
[2018-02-28T02:32:05.669613+00:00]     stream: TRACE   > 00060:  74 63 68 00 dd 00 00 00  03 30 00 d5 00 00 00 02  t c h . . . . .  . 0 . . . . . .
[2018-02-28T02:32:05.669737+00:00]     stream: TRACE   > 00070:  6e 61 6d 65 00 10 00 00  00 61 63 5f 6d 6f 6e 6f  n a m e . . . .  . a c _ m o n o
[2018-02-28T02:32:05.669869+00:00]     stream: TRACE   > 00080:  6c 6f 67 5f 6c 6f 67 73  00 02 74 79 70 65 00 0b  l o g _ l o g s  . . t y p e . .
[2018-02-28T02:32:05.669991+00:00]     stream: TRACE   > 00090:  00 00 00 63 6f 6c 6c 65  63 74 69 6f 6e 00 03 6f  . . . c o l l e  c t i o n . . o
[2018-02-28T02:32:05.670118+00:00]     stream: TRACE   > 000a0:  70 74 69 6f 6e 73 00 25  00 00 00 08 63 61 70 70  p t i o n s . %  . . . . c a p p
[2018-02-28T02:32:05.670235+00:00]     stream: TRACE   > 000b0:  65 64 00 01 01 73 69 7a  65 00 00 00 00 00 00 00  e d . . . s i z  e . . . . . . .
[2018-02-28T02:32:05.670357+00:00]     stream: TRACE   > 000c0:  d0 41 10 6d 61 78 00 c0  c6 2d 00 00 03 69 6e 66  . A . m a x . .  . - . . . i n f
[2018-02-28T02:32:05.670480+00:00]     stream: TRACE   > 000d0:  6f 00 10 00 00 00 08 72  65 61 64 4f 6e 6c 79 00  o . . . . . . r  e a d O n l y .
[2018-02-28T02:32:05.670605+00:00]     stream: TRACE   > 000e0:  00 00 03 69 64 49 6e 64  65 78 00 54 00 00 00 10  . . . i d I n d  e x . T . . . .
[2018-02-28T02:32:05.670721+00:00]     stream: TRACE   > 000f0:  76 00 02 00 00 00 03 6b  65 79 00 0e 00 00 00 10  v . . . . . . k  e y . . . . . .
[2018-02-28T02:32:05.670840+00:00]     stream: TRACE   > 00100:  5f 69 64 00 01 00 00 00  00 02 6e 61 6d 65 00 05  _ i d . . . . .  . . n a m e . .
[2018-02-28T02:32:05.670962+00:00]     stream: TRACE   > 00110:  00 00 00 5f 69 64 5f 00  02 6e 73 00 1e 00 00 00  . . . _ i d _ .  . n s . . . . .
[2018-02-28T02:32:05.671095+00:00]     stream: TRACE   > 00120:  61 63 6d 6f 6e 6f 6c 6f  67 6c 6f 67 73 2e 61 63  a c m o n o l o  g l o g s . a c
[2018-02-28T02:32:05.671229+00:00]     stream: TRACE   > 00130:  5f 6d 6f 6e 6f 6c 6f 67  5f 6c 6f 67 73 00 00 00  _ m o n o l o g  _ l o g s . . .
[2018-02-28T02:32:05.671334+00:00]     stream: TRACE   > 00140:  00 00 01 6f 6b 00 00 00  00 00 00 00 f0 3f 00     . . . o k . . .  . . . . . ? .
[2018-02-28T02:32:05.671379+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.671414+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.671450+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:05.671513+00:00]     mongoc: TRACE   > ENTRY: _mongoc_cmd_check_ok():1089
[2018-02-28T02:32:05.671558+00:00]     mongoc: TRACE   >  EXIT: _mongoc_cmd_check_ok():1095
[2018-02-28T02:32:05.671608+00:00]     client: TRACE   >  GOTO: _mongoc_client_command_with_opts():1828 done
[2018-02-28T02:32:05.671648+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.671688+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.671728+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_opts():1844
[2018-02-28T02:32:05.671796+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new_with_opts():226
[2018-02-28T02:32:05.671843+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[2018-02-28T02:32:05.671884+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():275
[2018-02-28T02:32:05.671926+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new_with_opts():345
[2018-02-28T02:32:05.671974+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_init():365
[2018-02-28T02:32:05.672015+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_new():37
[2018-02-28T02:32:05.672054+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_new():44
[2018-02-28T02:32:05.672094+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_init():376
[2018-02-28T02:32:05.680043+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[2018-02-28T02:32:05.680112+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[2018-02-28T02:32:05.680152+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[2018-02-28T02:32:05.680189+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[2018-02-28T02:32:05.680229+00:00] cursor-cursorid: TRACE   >  GOTO: _mongoc_cursor_cursorid_next():308 done
[2018-02-28T02:32:05.680263+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[2018-02-28T02:32:05.680298+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[2018-02-28T02:32:05.681769+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[2018-02-28T02:32:05.681821+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[2018-02-28T02:32:05.681858+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[2018-02-28T02:32:05.681895+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[2018-02-28T02:32:05.681932+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[2018-02-28T02:32:05.681968+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[2018-02-28T02:32:05.682005+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():1718
[2018-02-28T02:32:05.682039+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():1720
[2018-02-28T02:32:05.682074+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error_document():1731
[2018-02-28T02:32:05.682107+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error_document():1750
[2018-02-28T02:32:05.682146+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error_document():1772
[2018-02-28T02:32:05.682180+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error_document():1741
[2018-02-28T02:32:05.682231+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():515
[2018-02-28T02:32:05.682263+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_destroy():53
[2018-02-28T02:32:05.682313+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():532
[2018-02-28T02:32:05.682350+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():577
[2018-02-28T02:32:05.682388+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_destroy():62
[2018-02-28T02:32:05.682423+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():525
[2018-02-28T02:32:05.706473+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():798
[2018-02-28T02:32:05.706554+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():805
[2018-02-28T02:32:05.706612+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.706673+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.706715+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.706759+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.706854+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_init():894
[2018-02-28T02:32:05.706897+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_init():904
[2018-02-28T02:32:05.706959+00:00]     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_remove_many_with_opts():222
[2018-02-28T02:32:05.707003+00:00]     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_remove_many_with_opts():237
[2018-02-28T02:32:05.707043+00:00]     mongoc: TRACE   > ENTRY: _mongoc_bulk_operation_remove_with_opts():148
[2018-02-28T02:32:05.707092+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_init_delete():240
[2018-02-28T02:32:05.707177+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_init_bulk():187
[2018-02-28T02:32:05.707282+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_init_bulk():203
[2018-02-28T02:32:05.707364+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_delete_append():149
[2018-02-28T02:32:05.707444+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append():134
[2018-02-28T02:32:05.707516+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append():163
[2018-02-28T02:32:05.708910+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_delete_append():177
[2018-02-28T02:32:05.709091+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_init_delete():249
[2018-02-28T02:32:05.709200+00:00]     mongoc: TRACE   >  EXIT: _mongoc_bulk_operation_remove_with_opts():169
[2018-02-28T02:32:05.709309+00:00]     mongoc: TRACE   > ENTRY: mongoc_bulk_operation_execute():678
[2018-02-28T02:32:05.709775+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1650
[2018-02-28T02:32:05.709864+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1591
[2018-02-28T02:32:05.709962+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.710053+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.710129+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1617
[2018-02-28T02:32:05.710199+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1667
[2018-02-28T02:32:05.710274+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_execute():781
[2018-02-28T02:32:05.710345+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_opmsg():413
[2018-02-28T02:32:05.710428+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_init():282
[2018-02-28T02:32:05.710530+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_init():304
[2018-02-28T02:32:05.710634+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_append_opts():119
[2018-02-28T02:32:05.710711+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_append_opts():202
[2018-02-28T02:32:05.710836+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_assemble():564
[2018-02-28T02:32:05.710941+00:00]     mongoc: TRACE   > TRACE: mongoc_cmd_parts_assemble():592 Preparing 'delete'
[2018-02-28T02:32:05.710990+00:00]     client: TRACE   > ENTRY: mongoc_client_start_session():1150
[2018-02-28T02:32:05.711027+00:00]     mongoc: TRACE   > ENTRY: _mongoc_topology_pop_server_session():1288
[2018-02-28T02:32:05.711066+00:00]     mongoc: TRACE   >  EXIT: _mongoc_topology_pop_server_session():1314
[2018-02-28T02:32:05.711103+00:00]     client: TRACE   >  EXIT: mongoc_client_start_session():1154
[2018-02-28T02:32:05.711141+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_assemble():704
[2018-02-28T02:32:05.711210+00:00]    cluster: TRACE   > TRACE: mongoc_cluster_run_opmsg():2561 Function 'delete' is compressible: -1
[2018-02-28T02:32:05.711248+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():502
[2018-02-28T02:32:05.711284+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[2018-02-28T02:32:05.711328+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 0000000752C2BD50 [11]
[2018-02-28T02:32:05.711416+00:00]     stream: TRACE   > 00000:  96 00 00 00 04 00 00 00  00 00 00 00 dd 07 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.711508+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 5c 00 00  00 02 64 65 6c 65 74 65  . . . . . \ . .  . . d e l e t e
[2018-02-28T02:32:05.711658+00:00]     stream: TRACE   > 00020:  00 10 00 00 00 61 63 5f  6d 6f 6e 6f 6c 6f 67 5f  . . . . . a c _  m o n o l o g _
[2018-02-28T02:32:05.711908+00:00]     stream: TRACE   > 00030:  6c 6f 67 73 00 03 77 72  69 74 65 43 6f 6e 63 65  l o g s . . w r  i t e C o n c e
[2018-02-28T02:32:05.712088+00:00]     stream: TRACE   > 00040:  72 6e 00 0c 00 00 00 10  77 00 01 00 00 00 00 08  r n . . . . . .  w . . . . . . .
[2018-02-28T02:32:05.712240+00:00]     stream: TRACE   > 00050:  6f 72 64 65 72 65 64 00  01 02 24 64 62 00 0e 00  o r d e r e d .  . . $ d b . . .
[2018-02-28T02:32:05.712467+00:00]     stream: TRACE   > 00060:  00 00 61 63 6d 6f 6e 6f  6c 6f 67 6c 6f 67 73 00  . . a c m o n o  l o g l o g s .
[2018-02-28T02:32:05.712567+00:00]     stream: TRACE   > 00070:  00 01 24 00 00 00 64 65  6c 65 74 65 73 00 18 00  . . $ . . . d e  l e t e s . . .
[2018-02-28T02:32:05.712664+00:00]     stream: TRACE   > 00080:  00 00 03 71 00 05 00 00  00 00 10 6c 69 6d 69 74  . . . q . . . .  . . . l i m i t
[2018-02-28T02:32:05.712721+00:00]     stream: TRACE   > 00090:  00 00 00 00 00 00                                 . . . . . .
[2018-02-28T02:32:05.712752+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[2018-02-28T02:32:05.712789+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[2018-02-28T02:32:05.712824+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[2018-02-28T02:32:05.712878+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 000000075266F6E0 [11]
[2018-02-28T02:32:05.712960+00:00]     socket: TRACE   > 00000:  96 00 00 00 04 00 00 00  00 00 00 00 dd 07 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.713043+00:00]     socket: TRACE   > 00010:  00 00 00 00 00 5c 00 00  00 02 64 65 6c 65 74 65  . . . . . \ . .  . . d e l e t e
[2018-02-28T02:32:05.713129+00:00]     socket: TRACE   > 00020:  00 10 00 00 00 61 63 5f  6d 6f 6e 6f 6c 6f 67 5f  . . . . . a c _  m o n o l o g _
[2018-02-28T02:32:05.713217+00:00]     socket: TRACE   > 00030:  6c 6f 67 73 00 03 77 72  69 74 65 43 6f 6e 63 65  l o g s . . w r  i t e C o n c e
[2018-02-28T02:32:05.713297+00:00]     socket: TRACE   > 00040:  72 6e 00 0c 00 00 00 10  77 00 01 00 00 00 00 08  r n . . . . . .  w . . . . . . .
[2018-02-28T02:32:05.713382+00:00]     socket: TRACE   > 00050:  6f 72 64 65 72 65 64 00  01 02 24 64 62 00 0e 00  o r d e r e d .  . . $ d b . . .
[2018-02-28T02:32:05.713486+00:00]     socket: TRACE   > 00060:  00 00 61 63 6d 6f 6e 6f  6c 6f 67 6c 6f 67 73 00  . . a c m o n o  l o g l o g s .
[2018-02-28T02:32:05.713575+00:00]     socket: TRACE   > 00070:  00 01 24 00 00 00 64 65  6c 65 74 65 73 00 18 00  . . $ . . . d e  l e t e s . . .
[2018-02-28T02:32:05.713680+00:00]     socket: TRACE   > 00080:  00 00 03 71 00 05 00 00  00 00 10 6c 69 6d 69 74  . . . q . . . .  . . . l i m i t
[2018-02-28T02:32:05.713748+00:00]     socket: TRACE   > 00090:  00 00 00 00 00 00                                 . . . . . .
[2018-02-28T02:32:05.713967+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 150 (out of: 4), ret: 0
[2018-02-28T02:32:05.714045+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[2018-02-28T02:32:05.714096+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 150 (of 4) out of iovcnt=11
[2018-02-28T02:32:05.714142+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 150 -= 4
[2018-02-28T02:32:05.714188+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 146 -= 4
[2018-02-28T02:32:05.714235+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 142 -= 4
[2018-02-28T02:32:05.714280+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 138 -= 4
[2018-02-28T02:32:05.714328+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 134 -= 4
[2018-02-28T02:32:05.714418+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 130 -= 1
[2018-02-28T02:32:05.714485+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 129 -= 92
[2018-02-28T02:32:05.714530+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 37 -= 1
[2018-02-28T02:32:05.714577+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 36 -= 4
[2018-02-28T02:32:05.714621+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 32 -= 8
[2018-02-28T02:32:05.714699+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 24 -= 24
[2018-02-28T02:32:05.714745+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[2018-02-28T02:32:05.714782+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[2018-02-28T02:32:05.714825+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 0
[2018-02-28T02:32:05.714867+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[2018-02-28T02:32:05.714906+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[2018-02-28T02:32:05.714945+00:00]     stream: TRACE   > TRACE: _mongoc_stream_writev_full():509 writev returned: 150
[2018-02-28T02:32:05.714980+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():542
[2018-02-28T02:32:05.715005+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:05.715033+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.715067+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.715101+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.715139+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.715190+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.715228+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.715268+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D030 [1]
[2018-02-28T02:32:05.715324+00:00]     stream: TRACE   > 00000:  ae 00 00 00                                       . . . .
[2018-02-28T02:32:05.715357+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.715384+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.715417+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:05.715450+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:05.715480+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.715512+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.715545+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.715601+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.715642+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:05.715677+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:05.715718+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D030 [1]
[2018-02-28T02:32:05.715801+00:00]     stream: TRACE   > 00000:  be cf 03 00 04 00 00 00  dd 07 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.715878+00:00]     stream: TRACE   > 00010:  00 99 00 00 00 10 6e 00  00 00 00 00 04 77 72 69  . . . . . . n .  . . . . . w r i
[2018-02-28T02:32:05.715963+00:00]     stream: TRACE   > 00020:  74 65 45 72 72 6f 72 73  00 74 00 00 00 03 30 00  t e E r r o r s  . t . . . . 0 .
[2018-02-28T02:32:05.716055+00:00]     stream: TRACE   > 00030:  6c 00 00 00 10 69 6e 64  65 78 00 00 00 00 00 10  l . . . . i n d  e x . . . . . .
[2018-02-28T02:32:05.716140+00:00]     stream: TRACE   > 00040:  63 6f 64 65 00 14 00 00  00 02 65 72 72 6d 73 67  c o d e . . . .  . . e r r m s g
[2018-02-28T02:32:05.716227+00:00]     stream: TRACE   > 00050:  00 46 00 00 00 63 61 6e  6e 6f 74 20 72 65 6d 6f  . F . . . c a n  n o t   r e m o
[2018-02-28T02:32:05.716317+00:00]     stream: TRACE   > 00060:  76 65 20 66 72 6f 6d 20  61 20 63 61 70 70 65 64  v e   f r o m    a   c a p p e d
[2018-02-28T02:32:05.716408+00:00]     stream: TRACE   > 00070:  20 63 6f 6c 6c 65 63 74  69 6f 6e 3a 20 61 63 6d    c o l l e c t  i o n :   a c m
[2018-02-28T02:32:05.716499+00:00]     stream: TRACE   > 00080:  6f 6e 6f 6c 6f 67 6c 6f  67 73 2e 61 63 5f 6d 6f  o n o l o g l o  g s . a c _ m o
[2018-02-28T02:32:05.716611+00:00]     stream: TRACE   > 00090:  6e 6f 6c 6f 67 5f 6c 6f  67 73 00 00 00 01 6f 6b  n o l o g _ l o  g s . . . . o k
[2018-02-28T02:32:05.716830+00:00]     stream: TRACE   > 000a0:  00 00 00 00 00 00 00 f0  3f 00                    . . . . . . . .  ? .
[2018-02-28T02:32:05.716916+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:05.716966+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:05.717004+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:05.717049+00:00]     mongoc: TRACE   > ENTRY: _mongoc_cmd_check_ok():1089
[2018-02-28T02:32:05.717088+00:00]     mongoc: TRACE   >  EXIT: _mongoc_cmd_check_ok():1095
[2018-02-28T02:32:05.717132+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_merge():1014
[2018-02-28T02:32:05.717169+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_merge_arrays():965
[2018-02-28T02:32:05.717200+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_merge_arrays():996
[2018-02-28T02:32:05.717230+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_merge():1108
[2018-02-28T02:32:05.717264+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_opmsg():588
[2018-02-28T02:32:05.717301+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_execute():873
[2018-02-28T02:32:05.717335+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.717372+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.717408+00:00]     mongoc: TRACE   >  GOTO: mongoc_bulk_operation_execute():766 cleanup
[2018-02-28T02:32:05.717442+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_complete():1197
[2018-02-28T02:32:05.717490+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_complete():1293
[2018-02-28T02:32:05.717522+00:00]     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_execute():781
[2018-02-28T02:32:05.721574+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():798
[2018-02-28T02:32:05.721640+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():805
[2018-02-28T02:32:05.721690+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.721741+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.721784+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.721825+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.721881+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.721929+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.721992+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.722033+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.726163+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.726234+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.726296+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:05.726329+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:05.726404+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_opts():1724
[2018-02-28T02:32:05.726434+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[2018-02-28T02:32:05.726472+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():291
[2018-02-28T02:32:05.726510+00:00]    cluster: TRACE   > ENTRY: mongoc_cluster_stream_for_server():1650
[2018-02-28T02:32:05.726546+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_stream_for_server():1591
[2018-02-28T02:32:05.726599+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_handle_ismaster():493
[2018-02-28T02:32:05.726639+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_handle_ismaster():654
[2018-02-28T02:32:05.726772+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_stream_for_server():1617
[2018-02-28T02:32:05.726864+00:00]    cluster: TRACE   >  EXIT: mongoc_cluster_stream_for_server():1667
[2018-02-28T02:32:05.726912+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_append_opts():119
[2018-02-28T02:32:05.726957+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_append_opts():202
[2018-02-28T02:32:05.726995+00:00]     client: TRACE   > ENTRY: _mongoc_client_command_with_stream():1603
[2018-02-28T02:32:05.727028+00:00]     mongoc: TRACE   > ENTRY: mongoc_cmd_parts_assemble():564
[2018-02-28T02:32:05.727070+00:00]     mongoc: TRACE   > TRACE: mongoc_cmd_parts_assemble():592 Preparing 'drop'
[2018-02-28T02:32:05.727112+00:00]     client: TRACE   > ENTRY: mongoc_client_start_session():1150
[2018-02-28T02:32:05.727152+00:00]     mongoc: TRACE   > ENTRY: _mongoc_topology_pop_server_session():1288
[2018-02-28T02:32:05.727188+00:00]     mongoc: TRACE   >  EXIT: _mongoc_topology_pop_server_session():1314
[2018-02-28T02:32:05.727224+00:00]     client: TRACE   >  EXIT: mongoc_client_start_session():1154
[2018-02-28T02:32:05.727262+00:00]     mongoc: TRACE   >  EXIT: mongoc_cmd_parts_assemble():704
[2018-02-28T02:32:05.727294+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_stream():1617
[2018-02-28T02:32:05.727352+00:00]    cluster: TRACE   > TRACE: mongoc_cluster_run_opmsg():2561 Function 'drop' is compressible: -1
[2018-02-28T02:32:05.727389+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_writev_full():502
[2018-02-28T02:32:05.727424+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():150
[2018-02-28T02:32:05.727467+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():162 writev = 0000000752C2BD50 [7]
[2018-02-28T02:32:05.727559+00:00]     stream: TRACE   > 00000:  65 00 00 00 06 00 00 00  00 00 00 00 dd 07 00 00  e . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.727752+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 50 00 00  00 02 64 72 6f 70 00 10  . . . . . P . .  . . d r o p . .
[2018-02-28T02:32:05.727932+00:00]     stream: TRACE   > 00020:  00 00 00 61 63 5f 6d 6f  6e 6f 6c 6f 67 5f 6c 6f  . . . a c _ m o  n o l o g _ l o
[2018-02-28T02:32:05.728073+00:00]     stream: TRACE   > 00030:  67 73 00 03 77 72 69 74  65 43 6f 6e 63 65 72 6e  g s . . w r i t  e C o n c e r n
[2018-02-28T02:32:05.728187+00:00]     stream: TRACE   > 00040:  00 0c 00 00 00 10 77 00  01 00 00 00 00 02 24 64  . . . . . . w .  . . . . . . $ d
[2018-02-28T02:32:05.728303+00:00]     stream: TRACE   > 00050:  62 00 0e 00 00 00 61 63  6d 6f 6e 6f 6c 6f 67 6c  b . . . . . a c  m o n o l o g l
[2018-02-28T02:32:05.728373+00:00]     stream: TRACE   > 00060:  6f 67 73 00 00                                    o g s . .
[2018-02-28T02:32:05.728412+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_writev():199
[2018-02-28T02:32:05.728447+00:00]     socket: TRACE   > ENTRY: mongoc_socket_sendv():1351
[2018-02-28T02:32:05.728483+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_try_sendv():1256
[2018-02-28T02:32:05.728527+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1262 sendbuf = 00000007526E9A40 [7]
[2018-02-28T02:32:05.728636+00:00]     socket: TRACE   > 00000:  65 00 00 00 06 00 00 00  00 00 00 00 dd 07 00 00  e . . . . . . .  . . . . . . . .
[2018-02-28T02:32:05.728748+00:00]     socket: TRACE   > 00010:  00 00 00 00 00 50 00 00  00 02 64 72 6f 70 00 10  . . . . . P . .  . . d r o p . .
[2018-02-28T02:32:05.728879+00:00]     socket: TRACE   > 00020:  00 00 00 61 63 5f 6d 6f  6e 6f 6c 6f 67 5f 6c 6f  . . . a c _ m o  n o l o g _ l o
[2018-02-28T02:32:05.729014+00:00]     socket: TRACE   > 00030:  67 73 00 03 77 72 69 74  65 43 6f 6e 63 65 72 6e  g s . . w r i t  e C o n c e r n
[2018-02-28T02:32:05.729127+00:00]     socket: TRACE   > 00040:  00 0c 00 00 00 10 77 00  01 00 00 00 00 02 24 64  . . . . . . w .  . . . . . . $ d
[2018-02-28T02:32:05.729255+00:00]     socket: TRACE   > 00050:  62 00 0e 00 00 00 61 63  6d 6f 6e 6f 6c 6f 67 6c  b . . . . . a c  m o n o l o g l
[2018-02-28T02:32:05.729331+00:00]     socket: TRACE   > 00060:  6f 67 73 00 00                                    o g s . .
[2018-02-28T02:32:05.729546+00:00]     socket: TRACE   > TRACE: _mongoc_socket_try_sendv():1270 WSASend sent: 101 (out of: 4), ret: 0
[2018-02-28T02:32:05.729626+00:00]     socket: TRACE   >  EXIT: _mongoc_socket_try_sendv():1310
[2018-02-28T02:32:05.729679+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1363 Sent 101 (of 4) out of iovcnt=7
[2018-02-28T02:32:05.729727+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 101 -= 4
[2018-02-28T02:32:05.729773+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 97 -= 4
[2018-02-28T02:32:05.729819+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 93 -= 4
[2018-02-28T02:32:05.729866+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 89 -= 4
[2018-02-28T02:32:05.729911+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 85 -= 4
[2018-02-28T02:32:05.729958+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 81 -= 1
[2018-02-28T02:32:05.730005+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1390 still got bytes left: sent -= iov_len: 80 -= 80
[2018-02-28T02:32:05.730049+00:00]     socket: TRACE   > TRACE: mongoc_socket_sendv():1399 Finished the iovecs
[2018-02-28T02:32:05.730091+00:00]     socket: TRACE   >  EXIT: mongoc_socket_sendv():1431
[2018-02-28T02:32:05.730135+00:00]     socket: TRACE   > TRACE: mongoc_socket_errno():592 Current errno: 0
[2018-02-28T02:32:05.730175+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_writev():205
[2018-02-28T02:32:05.730213+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():165
[2018-02-28T02:32:05.730256+00:00]     stream: TRACE   > TRACE: _mongoc_stream_writev_full():509 writev returned: 101
[2018-02-28T02:32:05.730296+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_writev_full():542
[2018-02-28T02:32:05.730335+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:05.730369+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:05.730410+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:05.730448+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:05.730488+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:05.730548+00:00]     socket: TRACE   > TRACE: _mongoc_socket_capture_errno():68 setting errno: 10035 Unknown error
[2018-02-28T02:32:05.730623+00:00]     socket: TRACE   > TRACE: _mongoc_socket_errno_is_again():617 errno is: 10035
[2018-02-28T02:32:05.730671+00:00]     socket: TRACE   > ENTRY: _mongoc_socket_wait():148
[2018-02-28T02:32:07.265710+00:00]     socket: TRACE   >  GOTO: mongoc_socket_recv():1074 again
[2018-02-28T02:32:07.265803+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:07.265847+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:07.265892+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D1A0 [1]
[2018-02-28T02:32:07.265962+00:00]     stream: TRACE   > 00000:  5d 00 00 00                                       ] . . .
[2018-02-28T02:32:07.266003+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:07.266035+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:07.266074+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:07.266111+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():191
[2018-02-28T02:32:07.266144+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():269
[2018-02-28T02:32:07.266183+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():227
[2018-02-28T02:32:07.266221+00:00]     stream: TRACE   > ENTRY: _mongoc_stream_socket_readv():139
[2018-02-28T02:32:07.266260+00:00]     socket: TRACE   > ENTRY: mongoc_socket_recv():1055
[2018-02-28T02:32:07.266307+00:00]     socket: TRACE   >  EXIT: mongoc_socket_recv():1084
[2018-02-28T02:32:07.266346+00:00]     stream: TRACE   >  EXIT: _mongoc_stream_socket_readv():185
[2018-02-28T02:32:07.266391+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():237 readv = 000000075066D1A0 [1]
[2018-02-28T02:32:07.266506+00:00]     stream: TRACE   > 00000:  bf cf 03 00 06 00 00 00  dd 07 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
[2018-02-28T02:32:07.266628+00:00]     stream: TRACE   > 00010:  00 48 00 00 00 02 6e 73  00 1e 00 00 00 61 63 6d  . H . . . . n s  . . . . . a c m
[2018-02-28T02:32:07.266757+00:00]     stream: TRACE   > 00020:  6f 6e 6f 6c 6f 67 6c 6f  67 73 2e 61 63 5f 6d 6f  o n o l o g l o  g s . a c _ m o
[2018-02-28T02:32:07.266857+00:00]     stream: TRACE   > 00030:  6e 6f 6c 6f 67 5f 6c 6f  67 73 00 10 6e 49 6e 64  n o l o g _ l o  g s . . n I n d
[2018-02-28T02:32:07.266927+00:00]     stream: TRACE   > 00040:  65 78 65 73 57 61 73 00  07 00 00 00 01 6f 6b 00  e x e s W a s .  . . . . . o k .
[2018-02-28T02:32:07.266976+00:00]     stream: TRACE   > 00050:  00 00 00 00 00 00 f0 3f  00                       . . . . . . . ?  .
[2018-02-28T02:32:07.267003+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():240
[2018-02-28T02:32:07.267020+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():281
[2018-02-28T02:32:07.267041+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():230
[2018-02-28T02:32:07.267074+00:00]     mongoc: TRACE   > ENTRY: _mongoc_cmd_check_ok():1089
[2018-02-28T02:32:07.267097+00:00]     mongoc: TRACE   >  EXIT: _mongoc_cmd_check_ok():1095
[2018-02-28T02:32:07.267134+00:00]     client: TRACE   >  GOTO: _mongoc_client_command_with_opts():1828 done
[2018-02-28T02:32:07.267160+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():145
[2018-02-28T02:32:07.267180+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():151
[2018-02-28T02:32:07.267202+00:00]     client: TRACE   >  EXIT: _mongoc_client_command_with_opts():1844
[2018-02-28T02:32:07.267263+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_new_with_opts():226
[2018-02-28T02:32:07.267294+00:00]     mongoc: TRACE   > ENTRY: _mongoc_get_server_id_from_opts():268
[2018-02-28T02:32:07.267318+00:00]     mongoc: TRACE   >  EXIT: _mongoc_get_server_id_from_opts():275
[2018-02-28T02:32:07.267344+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_new_with_opts():345
[2018-02-28T02:32:07.267369+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_init():365
[2018-02-28T02:32:07.267391+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_new():37
[2018-02-28T02:32:07.267418+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_new():44
[2018-02-28T02:32:07.267439+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_init():376
[2018-02-28T02:32:07.269885+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[2018-02-28T02:32:07.269953+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[2018-02-28T02:32:07.269993+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[2018-02-28T02:32:07.270028+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[2018-02-28T02:32:07.270067+00:00] cursor-cursorid: TRACE   >  GOTO: _mongoc_cursor_cursorid_next():308 done
[2018-02-28T02:32:07.270100+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[2018-02-28T02:32:07.270136+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[2018-02-28T02:32:07.270203+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_next():1781
[2018-02-28T02:32:07.270234+00:00]     cursor: TRACE   > TRACE: mongoc_cursor_next():1786 cursor_id(0)
[2018-02-28T02:32:07.270270+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_next():284
[2018-02-28T02:32:07.270306+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_read_from_batch():150
[2018-02-28T02:32:07.270342+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_next():336
[2018-02-28T02:32:07.270378+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_next():1825
[2018-02-28T02:32:07.270410+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error():1718
[2018-02-28T02:32:07.270443+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error():1720
[2018-02-28T02:32:07.270476+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_error_document():1731
[2018-02-28T02:32:07.270509+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_error_document():1750
[2018-02-28T02:32:07.270544+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_error_document():1772
[2018-02-28T02:32:07.270581+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_error_document():1741
[2018-02-28T02:32:07.270623+00:00]     cursor: TRACE   > ENTRY: mongoc_cursor_destroy():515
[2018-02-28T02:32:07.270657+00:00] cursor-cursorid: TRACE   > ENTRY: _mongoc_cursor_cursorid_destroy():53
[2018-02-28T02:32:07.270695+00:00]     cursor: TRACE   > ENTRY: _mongoc_cursor_destroy():532
[2018-02-28T02:32:07.270737+00:00]     cursor: TRACE   >  EXIT: _mongoc_cursor_destroy():577
[2018-02-28T02:32:07.270774+00:00] cursor-cursorid: TRACE   >  EXIT: _mongoc_cursor_cursorid_destroy():62
[2018-02-28T02:32:07.270814+00:00]     cursor: TRACE   >  EXIT: mongoc_cursor_destroy():525
[2018-02-28T02:32:07.270944+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_command_destroy():880
[2018-02-28T02:32:07.270990+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_destroy():887
[2018-02-28T02:32:07.271030+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_destroy():911
[20 18-02-28T02:32:07.271068+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_destroy():919

I save logs directly from Monolog to MongoDB.
The ACMonologBundle is to search and analyse logs already saved.
The collection must be capped and by default it is not, so I create a command to drop and create the collection with the right schema ( bin/console ac:monolog:create --env=prod)
It seems work very well for over 2 years, before the recents updates.
This is maybe not a real bug but a very specific case ...

@jmikola
Copy link
Member

jmikola commented Mar 1, 2018

Is ACMonologBundle an open-source package, or is this your private bundle?

The most recent mongodb.debug trace you've shared looks to be entirely different from the previous trace. In this new trace, you're running the following commands:

  • listCollections on the "acmonologlogs" database, which returns one entry for a "ac_monolog_logs" capped collection.
  • delete on the "acmonologlogs.ac_monolog_logs" collection, with no query filter and a limit of zero (i.e. delete all), which elicits the "cannot remove from a capped collection" error response from the server.
  • drop on the "acmonologlogs" database to drop the "ac_monolog_logs" collection

Assuming those three commands are all executed from a command class in ACMonologBundle, I don't understand why the code is attempting to delete documents before dropping the collection. Have you identified the source of this delete command?

Assuming the code example in #1745 (comment) was taken from ACMonologBundle, I can tell you with certainty that none of the ODM SchemaManager methods should be executing a delete command. If that bundle is relying on ODM to create the capped collection based on document metadata for a "LogMessage" or similarly named class, the SchemaManager should still do nothing more than execute drop and create commands.

It seems work very well for over 2 years, before the recents updates.

Were you able to narrow down the break to a specific update of a single package/extension, or was this break only observed after updating multiple things in one shot?

@malarzm
Copy link
Member

malarzm commented Nov 4, 2023

Closing as nothing happened here in 5 years 👼

@malarzm malarzm closed this as completed Nov 4, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

3 participants