Unexpected behavior and logs from mongos

[bob]

Hi team,

I am using MongoDB 2.2.1 in replica set configuration (6 shards, 3 replica each)

==============================================================

My application (written in C) is set in cron and once started they acquires a connection and start pushing data into MongoDB usign mongodb-c-driver-0.81.

When I started push job, for some time all the requests got time out (I set operation timeout to 5 secs) and I seen unexpected error in mongos logs which can be found here http://pastebin.com/YrymGXPd.

Can you please help me understand what might have gone wrong.

Thank you in advanced.

[Asya Kamsky]

Hello Bob,

First of all, 2.2.1 is a pretty old version - I'd strongly recommend
at the very least updating to the latest patch version of 2.2 branch.

Secondly, your errors are quite straightforward:
DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50723
SocketException handling request, closing client connection: 9001
socket exception [2] server [127.0.0.1:50723]

They are all the same - socket exception, meaning connection was lost.
So I would check what happened to the other processes (since they
appear to be on the same physical host, it's not the network between
them but the other process dropping connection).

Asya

> --
> --
> You received this message because you are subscribed to the Google
> Groups "mongodb-user" group.
> To post to this group, send email to mongod...@googlegroups.com
> To unsubscribe from this group, send email to
> mongodb-user...@googlegroups.com
> See also the IRC channel -- freenode.net#mongodb
>
> ---
> You received this message because you are subscribed to the Google Groups
> "mongodb-user" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mongodb-user...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.

[Dilip Vaidya]

Thank you Asya for responding. I will be upgrading soon to version 2.4.

the logs I shared are from mongos process log. If I am not wrong,
mongos tries connect to config server or master shards which are not
running on same machine in my case and that's the reason of confusion.
Network was working for the time these logs were generated.

Please let me know if more information is needed.

> You received this message because you are subscribed to a topic in the
> Google Groups "mongodb-user" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/mongodb-user/am-iZz7Go6M/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to

> mongodb-user...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>

--


*Regards,Dilip Vaidya.*

[Asya Kamsky]

I'm afraid I'm going to have to disagree based on your own logs.

I see lots of messages like these:

Fri Feb  7 12:37:05 [conn18937] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50903

Fri Feb  7 12:37:05 [conn18937] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50903]

Fri Feb  7 12:37:05 [conn18985] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:51041

Fri Feb  7 12:37:05 [conn18857] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50648

Fri Feb  7 12:37:05 [conn18985] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:51041]

Fri Feb  7 12:37:05 [conn18857] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50648]

Fri Feb  7 12:37:05 [conn18894] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50763

Fri Feb  7 12:37:05 [conn18894] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50763]

Fri Feb  7 12:37:05 [conn18902] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50790

Fri Feb  7 12:37:05 [conn18902] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50790]

Fri Feb  7 12:37:05 [conn18883] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50740

Fri Feb  7 12:37:05 [conn18883] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50740]

Fri Feb  7 12:37:05 [conn18878] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50730

Fri Feb  7 12:37:05 [conn18878] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50730]

Fri Feb  7 12:37:05 [conn18876] DBException in process: socket exception [SEND_ERROR] for 127.0.0.1:50723

Fri Feb  7 12:37:05 [conn18876] SocketException handling request, closing client connection: 9001 socket exception [2] server [127.0.0.1:50723]

Since 127.0.0.1 is localhost (the same machine) you have to see what's running on it.  

Is the application code running on the machine that mongos is on?

If so then your application is not waiting for the response from mongos long enough and by the time mongos starts returning data to your application, the connection is already closed.

You initially said that you "set operation timeout to 5 secs" - what exactly does this mean?   If that means you're closing the connection on the client side, that's not the correct way to do it, since the server will still be running the operation till it's done.

Asya

[Dilip Vaidya]

Yes Asya, You are right. Application is running on same machine where 'mongos' is running. 

"set operation timeout to 5 secs" - 

I'm using 'mongodb-c-driver to interact with MongoDB. There is method called "mongo_set_op_timeout" which set time out on operations like read/write/update/delete etc. There is no connection timeout set on connection that has established between application and 'mongos' process.

'mongos' is continuously running on the machine. Application get started after every five minutes and established connection with mongos. On successful connection, it start writing / reading data to MongoDB. At the time of application start, I saw these error in the 'mongos' log file and I'm not sure why connection was getting broken down.

Regards,
Dilip Vaidya.

[Asya Kamsky]

What version of C driver is this?

There were quite a few things fixed related to timeouts...  See 

https://jira.mongodb.org/browse/CDRIVER-59

https://jira.mongodb.org/browse/CDRIVER-166

https://jira.mongodb.org/browse/CDRIVER-199

I would recommend removing the 5 second timeout as it may be obscuring the real problem at best and causing the problem at worst...

Asya

[Dilip Vaidya]

I am using latest version of MongoDB-C-Driver, i.e. 0.8.1. I think those all are fixed in this version. Do you still recommend not using set timeout API?

I am using them to avoid unnecessary waits from application, sometimes wait is for few seconds.

[Asya Kamsky]

I'm not sure how a wait for data to be returned can be "unnecessary".   If the queries are taking too long, the right thing to do is to tune the queries to take less time, not to close the connection to the DB.  

But I think we have the answer to your original question then, right?

Asya

[Dilip Vaidya]

Make sense. Yes, I got my questions answered. :)

Thanks you for your valuable response Asya.