[CDRIVER-2581] Error message of expiring "socketTimeoutMS" is changed Created: 02/Apr/18  Updated: 28/Oct/23  Resolved: 19/Apr/18

Status: Closed
Project: C Driver
Component/s: libmongoc
Affects Version/s: 1.9.3
Fix Version/s: 1.9.5, 1.10.0

Type: Bug Priority: Major - P3
Reporter: Yuichi Ogino Assignee: Kevin Albertson
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

OS : Red Hat Enterprise Linux Server release 7.1 (Maipo)



 Description   

At v1.8.2, when "socketTimeoutMS" expires, function "mongoc_database_command_simple" returns following error.

Failed to send "<COMMAND_NAME>" command with database "<DB_NAME>": socket error or timeout
 (e.g. Failed to send "saslStart" command with database "my_db": socket error or timeout)

But, at v1.9.3, this function returns following error.

Failed to read 4 bytes: socket error or timeout

It seems that amount of error information is reduced.
Is this change intentional?

stack trace (v1.9.3)

#0  bson_set_error (error=0x7fffffff30c0, domain=2, code=4,
    format=0x7ffff3144847 "Failed to buffer %u bytes")
    at src/bson/bson-error.c:69
#1  0x00007ffff30ef65e in _mongoc_buffer_fill (buffer=0x8b8778,
    stream=0x8b8660, min_bytes=4, timeout_msec=3000, error=0x7fffffff30c0)
    at src/mongoc/mongoc-buffer.c:290
#2  0x00007ffff3129404 in mongoc_stream_buffered_readv (stream=0x8b86f0,
    iov=0x7fffffff3370, iovcnt=1, min_bytes=4, timeout_msec=3000)
    at src/mongoc/mongoc-stream-buffered.c:239
#3  0x00007ffff31286eb in mongoc_stream_readv (stream=0x8b86f0,
    iov=0x7fffffff3370, iovcnt=1, min_bytes=4, timeout_msec=3000)
    at src/mongoc/mongoc-stream.c:235
#4  0x00007ffff3128830 in mongoc_stream_read (stream=0x8b86f0, buf=0x8bba60,
    count=4, min_bytes=4, timeout_msec=3000) at src/mongoc/mongoc-stream.c:279
#5  0x00007ffff30ef33d in _mongoc_buffer_append_from_stream (
    buffer=0x7fffffff3570, stream=0x8b86f0, size=4, timeout_msec=3000,
    error=0x7fffffff5b00) at src/mongoc/mongoc-buffer.c:217
#6  0x00007ffff30fe1d2 in mongoc_cluster_run_opmsg (cluster=0x8ac978,
    cmd=0x7fffffff4d00, reply=0x7fffffff3a80, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:2585
#7  0x00007ffff30fa38e in mongoc_cluster_run_command_private (
    cluster=0x8ac978, cmd=0x7fffffff4d00, reply=0x7fffffff3a80,
    error=0x7fffffff5b00) at src/mongoc/mongoc-cluster.c:552
#8  0x00007ffff30fa4c6 in mongoc_cluster_run_command_parts (cluster=0x8ac978,
    server_stream=0x8b9450, parts=0x7fffffff4d00, reply=0x7fffffff3a80,
    error=0x7fffffff5b00) at src/mongoc/mongoc-cluster.c:605
#9  0x00007ffff30fbae0 in _mongoc_cluster_auth_node_scram (cluster=0x8ac978,
    stream=0x8b86f0, sd=0x8ba1c0, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:1161
#10 0x00007ffff30fbfce in _mongoc_cluster_auth_node (cluster=0x8ac978,
    stream=0x8b86f0, sd=0x8ba1c0, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:1297
#11 0x00007ffff30fc41f in _mongoc_cluster_add_node (cluster=0x8ac978,
    server_id=1, error=0x7fffffff5b00) at src/mongoc/mongoc-cluster.c:1495
#12 0x00007ffff30fcd87 in mongoc_cluster_fetch_stream_pooled (
    cluster=0x8ac978, server_id=1, reconnect_ok=true, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:1834
#13 0x00007ffff30fc6cf in _mongoc_cluster_stream_for_server (cluster=0x8ac978,
    server_id=1, reconnect_ok=true, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:1601
#14 0x00007ffff30fd0e9 in _mongoc_cluster_stream_for_optype (cluster=0x8ac978,
    optype=MONGOC_SS_READ, read_prefs=0x0, error=0x7fffffff5b00)
    at src/mongoc/mongoc-cluster.c:1981
#15 0x00007ffff30fd120 in mongoc_cluster_stream_for_reads (cluster=0x8ac978,
    read_prefs=0x0, error=0x7fffffff5b00) at src/mongoc/mongoc-cluster.c:2011
#16 0x00007ffff30f6241 in _mongoc_client_command_with_opts (client=0x8ac970,
    db_name=0x8b7dc8 "my_db", command=0x7fffffff5a00,
    mode=MONGOC_CMD_READ, opts=0x0, flags=MONGOC_QUERY_NONE,
    default_prefs=0x0, default_rc=0x0, default_wc=0x0, reply=0x7fffffff5980,
    error=0x7fffffff5b00) at src/mongoc/mongoc-client.c:1778
#17 0x00007ffff310d4e8 in mongoc_database_command_simple (database=0x8b7dc0,
    command=0x7fffffff5a00, read_prefs=0x0, reply=0x7fffffff5980,
    error=0x7fffffff5b00) at src/mongoc/mongoc-database.c:214


After #0-#4, #5"_mongoc_buffer_append_from_stream" calls "bson_set_error" at the line 219,
and updates the error message.

181 bool
182 _mongoc_buffer_append_from_stream (mongoc_buffer_t *buffer,
183                                    mongoc_stream_t *stream,
184                                    size_t size,
185                                    int32_t timeout_msec,
186                                    bson_error_t *error)
187 {
...
217    ret = mongoc_stream_read (stream, buf, size, size, timeout_msec); //#4
218    if (ret != size) {
219       bson_set_error (error,
220                       MONGOC_ERROR_STREAM,
221                       MONGOC_ERROR_STREAM_SOCKET,
222                       "Failed to read %" PRIu64
223                       " bytes: socket error or timeout",
224                       (uint64_t) size);
225       RETURN (false);
226    }
227
228    buffer->len += ret;
229
230    RETURN (true);
231 }


#6"mongoc_cluster_run_opmsg" calls #5"_mongoc_buffer_append_from_stream"
at the line 2585, passing a constant argument "4".
#5"_mongoc_buffer_append_from_stream" returns false.

2495 static bool
2496 mongoc_cluster_run_opmsg (mongoc_cluster_t *cluster,
2497                           mongoc_cmd_t *cmd,
2498                           bson_t *reply,
2499                           bson_error_t *error)
2500 {
...
2585    ok = _mongoc_buffer_append_from_stream (
2586       &buffer, server_stream->stream, 4, cluster->sockettimeoutms, error);
2587    if (!ok) {
2588       mongoc_cluster_disconnect_node (
2589          cluster, server_stream->sd->id, true, error);
2590       bson_free (output);
2591       _mongoc_bson_init_if_set (reply);
2592       _mongoc_buffer_destroy (&buffer);
2593       return false;
2594    }
...
2683 }



 Comments   
Comment by Githook User [ 01/May/18 ]

Author:

{'email': 'kevin.albertson@10gen.com', 'username': 'kevinAlbs', 'name': 'Kevin Albertson'}

Message: CDRIVER-2581 improve opmsg cmd error msgs
Branch: debian
https://github.com/mongodb/mongo-c-driver/commit/e688cb4b8b714b5f93c53f405873b12f40322877

Comment by Githook User [ 01/May/18 ]

Author:

{'email': 'kevin.albertson@10gen.com', 'username': 'kevinAlbs', 'name': 'Kevin Albertson'}

Message: CDRIVER-2581 improve opmsg cmd error msgs
Branch: r1.9-dfsg
https://github.com/mongodb/mongo-c-driver/commit/e688cb4b8b714b5f93c53f405873b12f40322877

Comment by Githook User [ 19/Apr/18 ]

Author:

{'email': 'kevin.albertson@10gen.com', 'username': 'kevinAlbs', 'name': 'Kevin Albertson'}

Message: CDRIVER-2581 improve opmsg cmd error msgs
Branch: r1.9
https://github.com/mongodb/mongo-c-driver/commit/e688cb4b8b714b5f93c53f405873b12f40322877

Comment by Githook User [ 19/Apr/18 ]

Author:

{'email': 'kevin.albertson@10gen.com', 'username': 'kevinAlbs', 'name': 'Kevin Albertson'}

Message: CDRIVER-2581 improve opmsg cmd error msgs
Branch: master
https://github.com/mongodb/mongo-c-driver/commit/23bef5798b96963f85fa0d9a911a9064a5a2cdf4

Comment by Kevin Albertson [ 02/Apr/18 ]

Thanks for the detailed error report! I agree that this seems like a less desirable error message, but I don't currently know if this was intentional or an oversight. This is from the new OP_MSG implementation, the OP_QUERY command implementation still reports the same errors as it did in v1.8 (repeat the same process with a 3.4 MongoDB server).

Generated at Wed Feb 07 21:15:40 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.