I've been puzzling over intermittent failures in the HA test suite for a
while now, finally found the culprit. HA tests were setting
maxNegotiateTime between brokers to 1 sec for faster detection of
non-running brokers. Not really needed for the tests, I took it out and
that solved the problem.
BUT it turns out the sporadic >1 second delays are coming from
CyrusSasl::start!!? (see logs below) Can anybody tell my why that would
ever take more than 1000ms for (ANONYMOUS PLAIN) mechanisms that involve
0 encryption? Even the successful connect takes 300ms. I know this isn't
on the critical path but, wow. There was a time we could do <6ms latency
on clustered qpidd. Seems to me that's a bit more complex than saying
"no idea who you are, carry on!"
*** Client side failed connection
2015-02-25 08:29:37.460351321 [Client] debug Starting connection,
urls=[127.0.0.1:45983]
2015-02-25 08:29:37.460398537 [Client] info Trying to connect to
127.0.0.1:45983...
2015-02-25 08:29:37.460482649 [Client] debug Created IO thread: 0
2015-02-25 08:29:37.460529192 [Network] debug TCPConnector created for 0-10
2015-02-25 08:29:37.460538679 [Client] info Set TCP_NODELAY
2015-02-25 08:29:37.460787929 [System] info Connecting: 127.0.0.1:45983
2015-02-25 08:29:37.461252136 [Network] debug RECV
[[127.0.0.1:34247-127.0.0.1:45983]]: INIT(0-10)
2015-02-25 08:29:37.461299895 [Network] trace RECV
[[127.0.0.1:34247-127.0.0.1:45983]]: Frame[BEbe; channel=0;
{ConnectionStartBody:
server-properties={qpid.federation_tag:V2:36:str16(77800bff-a176-46c1-917a-32f136dee650)};
mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)};
locales=str16{V2:5:str16(en_US)}; }]
2015-02-25 08:29:37.463116303 [Security] debug CyrusSasl::start(ANONYMOUS PLAIN)
(Note delay > 1 sec here)
2015-02-25 08:29:38.839793753 [Security] debug min_ssf: 0, max_ssf: 256
2015-02-25 08:29:38.839851781 [Security] debug CyrusSasl::start(ANONYMOUS
PLAIN): selected ANONYMOUS response: 'anonymous@wallace'
2015-02-25 08:29:38.839963162 [Client] warning Connection
[127.0.0.1:34247-127.0.0.1:45983] closed
2015-02-25 08:29:38.840013732 [System] debug Exception constructed: Connection
[127.0.0.1:34247-127.0.0.1:45983] closed
2015-02-25 08:29:38.840112498 [Client] info Failed to connect to
127.0.0.1:45983: Connection [127.0.0.1:34247-127.0.0.1:45983] closed
qpid-receive: Failed to connect (reconnect disabled)
*** Broker side failed connection
2015-02-25 08:29:37.460916525 [Network] info Set TCP_NODELAY on connection to
127.0.0.1:34247
2015-02-25 08:29:37.461092469 [System] debug RECV
[qpid.0.0.0.0:45983-127.0.0.1:34247]: INIT(0-10)
2015-02-25 08:29:37.461109929 [Security] debug SASL: No Authentication Performed
2015-02-25 08:29:37.461129696 [Security] trace ACL ConnectionCounter new
connection: qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:37.461138034 [Broker] debug LinkRegistry::notifyConnection();
key=qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:37.461147332 [Model] trace Mgmt create connection.
id:qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:37.461154034 [Management] debug Management object (V1) added:
org.apache.qpid.broker:connection:qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:37.461174926 [Protocol] trace SENT
[qpid.0.0.0.0:45983-127.0.0.1:34247]: INIT(0-10)
2015-02-25 08:29:37.461187464 [Protocol] trace SENT
[qpid.0.0.0.0:45983-127.0.0.1:34247]: Frame[BEbe; channel=0;
{ConnectionStartBody:
server-properties={qpid.federation_tag:V2:36:str16(77800bff-a176-46c1-917a-32f136dee650)};
mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)};
locales=str16{V2:5:str16(en_US)}; }]
(Note > 1 sec delay)
2015-02-25 08:29:38.461053739 [System] error Connection
qpid.0.0.0.0:45983-127.0.0.1:34247 No protocol received closing
2015-02-25 08:29:38.461183175 [System] debug DISCONNECTED
[qpid.0.0.0.0:45983-127.0.0.1:34247]
2015-02-25 08:29:38.461546134 [Model] trace Mgmt destroying connection.
id:qpid.0.0.0.0:45983-127.0.0.1:34247 Statistics: {bytesFromClient:0,
bytesToClient:0, closing:False, framesFromClient:0, framesToClient:0,
msgsFromClient:0, msgsToClient:0}
2015-02-25 08:29:38.461830516 [Management] debug SEND raiseEvent (v2)
class=org.apache.qpid.broker.clientDisconnect
2015-02-25 08:29:38.461890961 [Model] debug Delete connection. user:
rhost:qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:38.461919543 [Management] trace Management object marked
deleted: org.apache.qpid.broker:connection:qpid.0.0.0.0:45983-127.0.0.1:34247
2015-02-25 08:29:38.461916800 [Broker] debug clean(): 0 messages remain; head
is now 0
2015-02-25 08:29:38.461959706 [Security] trace ACL ConnectionCounter closed:
qpid.0.0.0.0:45983-127.0.0.1:34247, userId:
*** Client side successful connection
2015-02-25 08:29:35.951259220 [Client] info Set TCP_NODELAY
2015-02-25 08:29:35.951401234 [System] info Connecting: 127.0.0.1:45983
2015-02-25 08:29:35.951827369 [Network] debug RECV
[[127.0.0.1:34244-127.0.0.1:45983]]: INIT(0-10)
2015-02-25 08:29:35.951864847 [Network] trace RECV
[[127.0.0.1:34244-127.0.0.1:45983]]: Frame[BEbe; channel=0;
{ConnectionStartBody:
server-properties={qpid.federation_tag:V2:36:str16(77800bff-a176-46c1-917a-32f136dee650)};
mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)};
locales=str16{V2:5:str16(en_US)}; }]
2015-02-25 08:29:35.953611949 [Security] debug CyrusSasl::start(ANONYMOUS PLAIN)
2015-02-25 08:29:36.209250530 [Security] debug min_ssf: 0, max_ssf: 256
2015-02-25 08:29:36.209305894 [Security] debug CyrusSasl::start(ANONYMOUS
PLAIN): selected ANONYMOUS response: 'anonymous@wallace'
2015-02-25 08:29:36.209372044 [Network] trace SENT
[[127.0.0.1:34244-127.0.0.1:45983]]: Frame[BEbe; channel=0;
{ConnectionStartOkBody:
client-properties={qpid.client_pid:F4:int32(4833),qpid.client_ppid:F4:int32(1767),qpid.client_process:V2:9:str16(qpid-send),qpid.session_flow:F4:int32(1)};
mechanism=ANONYMOUS; response=xxxxxx; locale=en_US; }]
*** Broker side successful connection
2015-02-25 08:29:35.951547191 [Network] info Set TCP_NODELAY on connection to
127.0.0.1:34244
2015-02-25 08:29:35.951682571 [System] debug RECV
[qpid.0.0.0.0:45983-127.0.0.1:34244]: INIT(0-10)
2015-02-25 08:29:35.951700608 [Security] debug SASL: No Authentication Performed
2015-02-25 08:29:35.951720263 [Security] trace ACL ConnectionCounter new
connection: qpid.0.0.0.0:45983-127.0.0.1:34244
2015-02-25 08:29:35.951729374 [Broker] debug LinkRegistry::notifyConnection();
key=qpid.0.0.0.0:45983-127.0.0.1:34244
2015-02-25 08:29:35.951739444 [Model] trace Mgmt create connection.
id:qpid.0.0.0.0:45983-127.0.0.1:34244
2015-02-25 08:29:35.951746298 [Management] debug Management object (V1) added:
org.apache.qpid.broker:connection:qpid.0.0.0.0:45983-127.0.0.1:34244
2015-02-25 08:29:35.951767607 [Protocol] trace SENT
[qpid.0.0.0.0:45983-127.0.0.1:34244]: INIT(0-10)
2015-02-25 08:29:35.951781016 [Protocol] trace SENT
[qpid.0.0.0.0:45983-127.0.0.1:34244]: Frame[BEbe; channel=0;
{ConnectionStartBody:
server-properties={qpid.federation_tag:V2:36:str16(77800bff-a176-46c1-917a-32f136dee650)};
mechanisms=str16{V2:9:str16(ANONYMOUS), V2:5:str16(PLAIN)};
locales=str16{V2:5:str16(en_US)}; }]
2015-02-25 08:29:36.209455813 [Protocol] trace RECV
[qpid.0.0.0.0:45983-127.0.0.1:34244]: Frame[BEbe; channel=0;
{ConnectionStartOkBody:
client-properties={qpid.client_pid:F4:int32(4833),qpid.client_ppid:F4:int32(1767),qpid.client_process:V2:9:str16(qpid-send),qpid.session_flow:F4:int32(1)};
mechanism=ANONYMOUS; response=xxxxxx; locale=en_US; }]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
