Loading...

Type: Bug
Resolution: Done
Priority: Major - P3
Fix Version/s: 1.0.0-beta2
Affects Version/s: 1.0.0-beta1
Component/s: None
Labels:
None

Streams don't appear to be cleanly killed on failure.

For example, on failed authentication the stream still sticks around, causing a "SSL/TLS already set-up for this stream" when attempting to authenticate again.

It also appears to be attempting to authenticate twice every for every stream:

[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Connecting to '192.168.112.10:2300[mongodb://username@192.168.112.10:2300/phongo?ssl=true&authMechanism=MONGODB-X509]'
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Created: RSRC#9 as '192.168.112.10:2300[mongodb://username@192.168.112.10:2300/phongo?ssl=true&authMechanism=MONGODB-X509]'
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Enabling SSL
[2015-09-11T21:31:35+00:00]     PHONGO: TRACE   >  EXIT: phongo_stream_initiator():1282
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():148
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():160 writev = 0x7f9d669fcf88 [9]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  3a 00 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  : . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+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 . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  00 00 00 ff ff ff ff 13  00 00 00 10 69 73 4d 61  . . . . . . . .  . . . . i s M a
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00030:  73 74 65 72 00 01 00 00  00 00                    s t e r . . . .  . .
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 0
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():163
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():293
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 0
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 4 wanted: 0
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371c200 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  c2 00 00 00                                       . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():323
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_try_append_from_stream():293
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 0
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 190 wanted: 0
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371c1d0 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  c4 00 00 00 01 00 00 00  01 00 00 00 08 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 00 00 00  00 00 00 00 01 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  9e 00 00 00 08 69 73 6d  61 73 74 65 72 00 01 10  . . . . . i s m  a s t e r . . .
[2015-09-11T21:31:35+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
[2015-09-11T21:31:35+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
[2015-09-11T21:31:35+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 . . .
[2015-09-11T21:31:35+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
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00070:  65 00 e8 03 00 00 09 6c  6f 63 61 6c 54 69 6d 65  e . . . . . . l  o c a l T i m e
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00080:  00 2c 19 52 be 4f 01 00  00 10 6d 61 78 57 69 72  . , . R . O . .  . . m a x W i r
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00090:  65 56 65 72 73 69 6f 6e  00 03 00 00 00 10 6d 69  e V e r s i o n  . . . . . . m i
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 000a0:  6e 57 69 72 65 56 65 72  73 69 6f 6e 00 00 00 00  n W i r e V e r  s i o n . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 000b0:  00 01 6f 6b 00 00 00 00  00 00 00 f0 3f 00        . . o k . . . .  . . . . ? .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_try_append_from_stream():323
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   > ENTRY: mongoc_topology_description_select():430
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: mongoc_topology_description_select():442
[2015-09-11T21:31:35+00:00]    cluster: INFO    > X509: got username (username) from URI
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_run_command():105
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():148
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():160 writev = 0x7f9d6696ede8 [9]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  71 00 00 00 01 00 00 00  00 00 00 00 d4 07 00 00  q . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00010:  04 00 00 00 24 65 78 74  65 72 6e 61 6c 2e 24 63  . . . . $ e x t  e r n a l . $ c
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  6d 64 00 00 00 00 00 ff  ff ff ff 46 00 00 00 10  m d . . . . . .  . . . F . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00030:  61 75 74 68 65 6e 74 69  63 61 74 65 00 01 00 00  a u t h e n t i  c a t e . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00040:  00 02 6d 65 63 68 61 6e  69 73 6d 00 0d 00 00 00  . . m e c h a n  i s m . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00050:  4d 4f 4e 47 4f 44 42 2d  58 35 30 39 00 02 75 73  M O N G O D B -  X 5 0 9 . . u s
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00060:  65 72 00 09 00 00 00 75  73 65 72 6e 61 6d 65 00  e r . . . . . u  s e r n a m e .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00070:  00                                                .
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():163
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():150
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 4 wanted: 4
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371bf90 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  57 00 00 00                                       W . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():186
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():150
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 83 wanted: 83
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371bf90 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  c5 00 00 00 01 00 00 00  01 00 00 00 08 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 00 00 00  00 00 00 00 01 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  33 00 00 00 01 6f 6b 00  00 00 00 00 00 00 00 00  3 . . . . o k .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00030:  02 65 72 72 6d 73 67 00  0c 00 00 00 61 75 74 68  . e r r m s g .  . . . . a u t h
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00040:  20 66 61 69 6c 65 64 00  10 63 6f 64 65 00 12 00    f a i l e d .  . c o d e . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00050:  00 00 00                                          . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():186
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > TRACE: _mongoc_cluster_run_command():156 &buffer = 0x7f9d6696e550 [87]
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00000:  57 00 00 00 c5 00 00 00  01 00 00 00 01 00 00 00  W . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00010:  08 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00020:  01 00 00 00 33 00 00 00  01 6f 6b 00 00 00 00 00  . . . . 3 . . .  . o k . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00030:  00 00 00 00 02 65 72 72  6d 73 67 00 0c 00 00 00  . . . . . e r r  m s g . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00040:  61 75 74 68 20 66 61 69  6c 65 64 00 10 63 6f 64  a u t h   f a i  l e d . . c o d
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00050:  65 00 12 00 00 00 00                              e . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_run_command():179
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_add_node():1148
[2015-09-11T21:31:35+00:00]    cluster: DEBUG   > Adding new server to cluster: 192.168.112.10:2300
[2015-09-11T21:31:35+00:00]    cluster: INFO    > X509: got username (username) from URI
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > ENTRY: _mongoc_cluster_run_command():105
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_writev():148
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_writev():160 writev = 0x7f9d6696ede8 [9]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  71 00 00 00 02 00 00 00  00 00 00 00 d4 07 00 00  q . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00010:  04 00 00 00 24 65 78 74  65 72 6e 61 6c 2e 24 63  . . . . $ e x t  e r n a l . $ c
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  6d 64 00 00 00 00 00 ff  ff ff ff 46 00 00 00 10  m d . . . . . .  . . . F . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00030:  61 75 74 68 65 6e 74 69  63 61 74 65 00 01 00 00  a u t h e n t i  c a t e . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00040:  00 02 6d 65 63 68 61 6e  69 73 6d 00 0d 00 00 00  . . m e c h a n  i s m . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00050:  4d 4f 4e 47 4f 44 42 2d  58 35 30 39 00 02 75 73  M O N G O D B -  X 5 0 9 . . u s
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00060:  65 72 00 09 00 00 00 75  73 65 72 6e 61 6d 65 00  e r . . . . . u  s e r n a m e .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00070:  00                                                .
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_writev():163
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():150
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 4 wanted: 4
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371bfa0 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  57 00 00 00                                       W . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():186
[2015-09-11T21:31:35+00:00]     buffer: TRACE   > ENTRY: _mongoc_buffer_append_from_stream():150
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_read():265
[2015-09-11T21:31:35+00:00]     stream: TRACE   > ENTRY: mongoc_stream_readv():225
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Setting timeout to: 300000
[2015-09-11T21:31:35+00:00]     PHONGO: DEBUG   > Reading got: 83 wanted: 83
[2015-09-11T21:31:35+00:00]     stream: TRACE   > TRACE: mongoc_stream_readv():234 readv = 0x7fff3371bfa0 [1]
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00000:  c6 00 00 00 02 00 00 00  01 00 00 00 08 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00010:  00 00 00 00 00 00 00 00  00 00 00 00 01 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00020:  33 00 00 00 01 6f 6b 00  00 00 00 00 00 00 00 00  3 . . . . o k .  . . . . . . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00030:  02 65 72 72 6d 73 67 00  0c 00 00 00 61 75 74 68  . e r r m s g .  . . . . a u t h
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00040:  20 66 61 69 6c 65 64 00  10 63 6f 64 65 00 12 00    f a i l e d .  . c o d e . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   > 00050:  00 00 00                                          . . .
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_readv():236
[2015-09-11T21:31:35+00:00]     stream: TRACE   >  EXIT: mongoc_stream_read():277
[2015-09-11T21:31:35+00:00]     buffer: TRACE   >  EXIT: _mongoc_buffer_append_from_stream():186
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > TRACE: _mongoc_cluster_run_command():156 &buffer = 0x7f9d6696e550 [87]
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00000:  57 00 00 00 c6 00 00 00  02 00 00 00 01 00 00 00  W . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00010:  08 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  . . . . . . . .  . . . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00020:  01 00 00 00 33 00 00 00  01 6f 6b 00 00 00 00 00  . . . . 3 . . .  . o k . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00030:  00 00 00 00 02 65 72 72  6d 73 67 00 0c 00 00 00  . . . . . e r r  m s g . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00040:  61 75 74 68 20 66 61 69  6c 65 64 00 10 63 6f 64  a u t h   f a i  l e d . . c o d
[2015-09-11T21:31:35+00:00]    cluster: TRACE   > 00050:  65 00 12 00 00 00 00                              e . . . . . .
[2015-09-11T21:31:35+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_run_command():179
[2015-09-11T21:31:35+00:00]    cluster: WARNING > Failed authentication to 192.168.112.10:2300
[2015-09-11T21:31:35+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_add_node():1176
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   > ENTRY: mongoc_server_description_destroy():154
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: mongoc_server_description_destroy():160
[2015-09-11T21:31:35+00:00]    cluster: TRACE   >  EXIT: _mongoc_cluster_select_by_optype():1471
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_command_execute():957
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  GOTO: mongoc_bulk_operation_execute():429 cleanup
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_complete():1341
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_complete():1389
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: mongoc_bulk_operation_execute():438
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_init():998
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_init():1008
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   > ENTRY: _mongoc_write_result_destroy():1015
[2015-09-11T21:31:35+00:00]     mongoc: TRACE   >  EXIT: _mongoc_write_result_destroy():1023
MongoDB\Driver\Exception\AuthenticationException: auth failed

is related to

CDRIVER-836 Only try to authenticate once on failure

Closed

PHPC-407 SSL/TLS already set-up for this stream

Closed

related to

PHPC-251 Authentication error result in weird error message

Closed

PHPC-706 Redundant SSL/TLS initialization for persistent streams

Closed

PHPC-406 Use constant-time hash comparison functions

Closed

Details

Description

Attachments

Issue Links

Activity

People

Dates