Closed Bug 858394 Opened 11 years ago Closed 10 years ago

Some SSL/TLS servers disconnect if the client sends valid session resumption state [seen with Chatzilla, Thunderbird chat]

Categories

(NSS :: Libraries, defect)

Product:
NSS
Component:
Libraries
Version:
3.15.2
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: svetlana, Assigned: KaiE)

Details

Attachments

(2 files)

gsb stack on nsSocketTransport::OnMsgOutputClosed breakpoint
30.55 KB, text/plain
Details
tcpdump.log
12.91 KB, text/plain
Details 
Steps to reproduce:
 1) /sslserver chat.freenode.net 6697
 2) wait for motd to display etc
 3) /disconnect
 4) click reconnect link

Expected:
 A reconnect.

Actual result:
 An error message "Connection to freenode is reset. Reconnecting in 15 seconds."
 cZ tries to reconnect repeatedly with the same result. Restarting cZ "fixes" the issue.

The issue happens with SSL only. After clicking "Reconnect", console is spammed with this:
 cz: >>> goto-url-newtab url: x-cz-command:reconnect anchor: null <<<
 cz: >>> reconnect reason: null <<<
 cz: >>> focus-input <<<
 cz: Level 1: 'do-connect', network[chat.freenode.net:6697].onDoConnect
 cz: Level 1: 'startconnect', network[chat.freenode.net:6697].onStartConnect
 data   : Connecting to chat.freenode.net:6697:6697, attempt 1 of -1...
 cz: >>> create-tab-for-view view: [object Object] <<<
 cz: Level 1: 'connect', server[chat.freenode.net].onConnect
 cz: Level 1: 'senddata', server[chat.freenode.net].onSendData
 data   : 'NICK gatertsertsezrg\n'
 cz: Level 1: 'senddata', server[chat.freenode.net].onSendData
 data   : 'USER chatzilla * * :New Now Know How\n'
 cz: Level 1: 'disconnect', server[chat.freenode.net].onDisconnect
 cz: Level 2: 'disconnect', network[chat.freenode.net:6697].onDisconnect
 cz: >>> create-tab-for-view view: [object Object] <<<
 cz: >>> sync-header <<<
 cz: hook #0 'event-tracer' had an error!
 cz: TypeError: e.destObject.connection is null @ <chrome://chatzilla/content/lib/js/irc-debug.js> 18
 cz: Can't send to disconnected socket
 cz: sendQueue flushed.
Mozilla/5.0 (X11; Linux x86_64; rv:23.0) Gecko/20100101 Firefox/23.0 SeaMonkey/2.20a1 ID:20130403003001 c-c:4ad03358510a m-c:97cfc16ba5dc

with a rather recent ChatZilla 0.9.90+ build from a SeaMonkey nightly of a few days ago.

Works for me: did /disconnect, clicked the [Reconnect] link, and waited. Connection was established on second attempt with no intervention on my part, as follows:

[Friday 17:57:15]	[QUIT]	Disconnected from irc://freenode/ (ircs://chat.eu.freenode.net:6697/). [Reconnect]
[Friday 17:57:24]	[INFO]	Connecting to irc://freenode/ (ircs://chat.eu.freenode.net:6697/)… [Cancel]
[Friday 17:57:32]	[ERROR]	Connection to irc://freenode/ (ircs://chat.eu.freenode.net:6697/) reset. [Help] 19 attempts left, reconnecting in 15 seconds. [Cancel]
[Friday 17:57:57]	[INFO]	Connecting to irc://freenode/ (ircs://irc.freenode.net:6697/)… [Cancel]
[Friday 17:58:05]	===	*** Looking up your hostname...
	===	*** Checking Ident
	===	*** No Ident response
	===	*** Couldn't look up your hostname
	===	Welcome to the freenode Internet Relay Chat Network tonymec
	===	Your host is morgan.freenode.net[64.32.24.176/6697], running version ircd-seven-1.1.3

(etc.)
P.S. I have a networks.txt with an entry for freenode, but as you can see above, all connections happened over SSL.
(In reply to Tony Mechelynck [:tonymec] from comment #2)
> P.S. I have a networks.txt with an entry for freenode, but as you can see
> above, all connections happened over SSL.

Can you try (re)connecting to rajaniemi.freenode.net 6697?
NSPR logging (with 'all:4' level) for the /reconnect and subsequent error gives this information:


-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnFocusWindow, aWindow=ad5397a0, mLastFocusedWindow=ad5397a0
-1219901696[b722f1c0]: GtkIMModule(9f07b860): Focus, sLastFocusedModule=9f07b860
-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnFocusChangeInGecko, aFocus=YES, mCompositionState=NotComposing, mIsIMFocused=YES, mIgnoreNativeCompositionEvent=NO
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [C] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 9 weight: 400 width: 0 style: normal TEXTRUN [ChatZilla] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [I] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 3 weight: 400 width: 0 style: normal TEXTRUN [IRC] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [E] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [Edit] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [V] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [View] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [H] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [Help] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 15 weight: 400 width: 0 style: normal TEXTRUN [gatertsertsezrg] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 8 weight: 400 width: 0 style: normal TEXTRUN [*client*] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 22 weight: 700 width: 0 style: normal TEXTRUN [chat.freenode.net:6697] ENDTEXTRUN
-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnKeyEvent, aCaller=ad5397a0, aKeyDownEventWasSent=FALSE
-1219901696[b722f1c0]:     aEvent: type=GDK_KEY_PRESS, keyval=Return, unicode=0x0
-1219901696[b722f1c0]:     filterThisEvent=FALSE (isFiltered=NO, mFilterKeyEvent=YES)
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrun) fontgroup: [serif] lang: en-us script: 25 len 6 weight: 700 width: 0 style: normal TEXTRUN [[INFO]] ENDTEXTRUN
-1219901696[b722f1c0]: (textrun) fontgroup: [serif] lang: en-us script: 25 len 6 weight: 700 width: 0 style: normal TEXTRUN [[INFO]] ENDTEXTRUN
-1219901696[b722f1c0]: (textrun) fontgroup: [serif] lang: en-us script: 0 len 4 weight: 400 width: 0 style: normal TEXTRUN [)… [] ENDTEXTRUN
-1219901696[b722f1c0]: creating nsSocketTransport @9bc7c700
-1219901696[b722f1c0]: nsSocketTransport::Init [this=9bc7c700 host=chat.freenode.net:6697 proxy=:0]
-1219901696[b722f1c0]: Reset callbacks for secinfo=0 callbacks=9ca23890
-1219901696[b722f1c0]: nsSocketTransport::OpenOutputStream [this=9bc7c700 flags=0]
-1219901696[b722f1c0]: STS dispatch [9b6514c8]
-1318364352[b722fcc0]:     ...returned after 11862 milliseconds
-1318364352[b722fcc0]: nsSocketOutputStream::AsyncWait [this=9bc7c808]
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = -1 milliseconds
-1219901696[b722f1c0]: nsSocketTransport::PostEvent [this=9bc7c700 type=0 status=0 param=0]
-1219901696[b722f1c0]: STS dispatch [9bcf95a0]
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketEvent [this=9bc7c700 type=0 status=0 param=0]
-1318364352[b722fcc0]:   MSG_ENSURE_CONNECT
-1318364352[b722fcc0]: nsSocketTransport::ResolveHost [this=9bc7c700]
-1318364352[b722fcc0]: nsSocketTransport::SendStatus [this=9bc7c700 status=804b0003]
-1318364352[b722fcc0]: Resolving host [chat.freenode.net].
-1318364352[b722fcc0]: Using cached record for host [chat.freenode.net].
-1318364352[b722fcc0]: nsSocketTransport::PostEvent [this=9bc7c700 type=1 status=0 param=9bcf95c0]
-1318364352[b722fcc0]: STS dispatch [9bcf9600]
-1318364352[b722fcc0]:   advancing to STATE_RESOLVING
-1318364352[b722fcc0]: STS poll iter [0]
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = 0 milliseconds
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketEvent [this=9bc7c700 type=1 status=0 param=9bcf95c0]
-1318364352[b722fcc0]: nsSocketTransport::SendStatus [this=9bc7c700 status=804b000b]
-1318364352[b722fcc0]:   MSG_DNS_LOOKUP_COMPLETE
-1318364352[b722fcc0]: Checking blacklist for host [chat.freenode.net], host record [9caae040].
-1318364352[b722fcc0]: nsSocketTransport::InitiateSocket [this=9bc7c700]
-1318364352[b722fcc0]: nsSocketTransport::BuildSocket [this=9bc7c700]
-1318364352[b722fcc0]:   pushing io layer [0:ssl]
-1318364352[b722fcc0]:   [secinfo=9cabefc0 callbacks=9ca23890]
-1318364352[b722fcc0]: nsSocketTransportService::AttachSocket [handler=9bc7c700]
-1318364352[b722fcc0]: nsSocketTransportService::AddToIdleList [handler=9bc7c700]
-1318364352[b722fcc0]:   active=0 idle=1
-1318364352[b722fcc0]:   advancing to STATE_CONNECTING
-1318364352[b722fcc0]: nsSocketTransport::SendStatus [this=9bc7c700 status=804b0007]
-1318364352[b722fcc0]:   trying address: 193.219.128.49
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   idle [0] { handler=9bc7c700 condition=0 pollflags=6 }
-1318364352[b722fcc0]: nsSocketTransportService::AddToPollList [handler=9bc7c700]
-1318364352[b722fcc0]:   active=1 idle=1
-1318364352[b722fcc0]: nsSocketTransportService::RemoveFromIdleList [handler=9bc7c700]
-1318364352[b722fcc0]:   active=1 idle=0
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1219901696[b722f1c0]: nsSocketTransport::OpenInputStream [this=9bc7c700 flags=0]
-1219901696[b722f1c0]: STS dispatch [9c0fbd88]
-1318364352[b722fcc0]:     ...returned after 1 milliseconds
-1318364352[b722fcc0]: nsSocketInputStream::Read [this=9bc7c7e8 count=32768]
-1318364352[b722fcc0]: nsSocketInputStream::AsyncWait [this=9bc7c7e8]
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=6 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1219901696[b722f1c0]: nsSocketTransport::PostEvent [this=9bc7c700 type=0 status=0 param=0]
-1219901696[b722f1c0]: STS dispatch [9bcf9720]
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketEvent [this=9bc7c700 type=0 status=0 param=0]
-1318364352[b722fcc0]:   MSG_ENSURE_CONNECT
-1318364352[b722fcc0]:   ignoring redundant event
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=6 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnKeyEvent, aCaller=ad5397a0, aKeyDownEventWasSent=FALSE
-1219901696[b722f1c0]:     aEvent: type=GDK_KEY_RELEASE, keyval=Return, unicode=0x0
-1219901696[b722f1c0]:     filterThisEvent=FALSE (isFiltered=NO, mFilterKeyEvent=YES)
-1318364352[b722fcc0]:     ...returned after 434 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketReady [this=9bc7c700 outFlags=2]
-1318364352[b722fcc0]:   advancing to STATE_TRANSFERRING
-1318364352[b722fcc0]: nsSocketTransport::SendStatus [this=9bc7c700 status=804b0004]
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=7 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketReady [this=9bc7c700 outFlags=3]
-1318364352[b722fcc0]: nsSocketOutputStream::OnSocketReady [this=9bc7c808 cond=0]
-1318364352[b722fcc0]: nsSocketInputStream::OnSocketReady [this=9bc7c7e8 cond=0]
-1318364352[b722fcc0]: STS dispatch [9c0fbd88]
-1318364352[b722fcc0]: nsSocketInputStream::Read [this=9bc7c7e8 count=32768]
-1318364352[b722fcc0]:   calling PR_Read [count=32768]
-1318364352[b722fcc0]:   PR_Read returned [n=-1]
-1318364352[b722fcc0]: nsSocketInputStream::AsyncWait [this=9bc7c7e8]
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=5 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1318364352[b722fcc0]:     ...returned after 1 milliseconds
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=5 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1219901696[b722f1c0]: STS dispatch [9b6514c8]
-1318364352[b722fcc0]:     ...returned after 65 milliseconds
-1318364352[b722fcc0]: nsSocketOutputStream::Write [this=9bc7c808 count=21]
-1318364352[b722fcc0]:   calling PR_Write [count=21]
-1318364352[b722fcc0]:   PR_Write returned [n=-1]
-1318364352[b722fcc0]: nsSocketOutputStream::AsyncWait [this=9bc7c808]
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=0 pollflags=7 }
-1318364352[b722fcc0]:   calling PR_Poll [active=1 idle=0]
-1318364352[b722fcc0]: poll timeout: 65535
-1318364352[b722fcc0]:     timeout = 65535000 milliseconds
-1318364352[b722fcc0]:     ...returned after 377 milliseconds
-1318364352[b722fcc0]: nsSocketTransport::OnSocketReady [this=9bc7c700 outFlags=3]
-1318364352[b722fcc0]: nsSocketOutputStream::OnSocketReady [this=9bc7c808 cond=0]
-1318364352[b722fcc0]: STS dispatch [9b6514c8]
-1318364352[b722fcc0]: nsSocketInputStream::OnSocketReady [this=9bc7c7e8 cond=0]
-1318364352[b722fcc0]: STS dispatch [9c0fbd88]
-1318364352[b722fcc0]: nsSocketOutputStream::Write [this=9bc7c808 count=21]
-1318364352[b722fcc0]:   calling PR_Write [count=21]
-1318364352[b722fcc0]:   PR_Write returned [n=-1]
-1318364352[b722fcc0]: ErrorAccordingToNSPR [in=-5961 out=804b0014]
-1318364352[b722fcc0]: nsSocketTransport::OnMsgOutputClosed [this=9bc7c700 reason=804b0014]
-1318364352[b722fcc0]: nsSocketOutputStream::CloseWithStatus [this=9bc7c808 reason=0]
-1318364352[b722fcc0]: nsSocketOutputStream::CloseWithStatus [this=9bc7c808 reason=80470002]
-1318364352[b722fcc0]: STS dispatch [9b6514c8]
-1318364352[b722fcc0]: STS poll iter [0]
-1318364352[b722fcc0]:   active [0] { handler=9bc7c700 condition=804b0014 pollflags=0 }
-1318364352[b722fcc0]: nsSocketTransportService::DetachSocket [handler=9bc7c700]
-1318364352[b722fcc0]: nsSocketTransport::OnSocketDetached [this=9bc7c700 cond=804b0014]
-1318364352[b722fcc0]: nsSocketTransport::RecoverFromError [this=9bc7c700 state=4 cond=804b0014]
-1318364352[b722fcc0]: nsSocketInputStream::OnSocketReady [this=9bc7c7e8 cond=804b0014]
-1318364352[b722fcc0]: nsSocketOutputStream::OnSocketReady [this=9bc7c808 cond=804b0014]
-1318364352[b722fcc0]: nsSocketTransport: calling PR_Close [this=9bc7c700]
-1318364352[b722fcc0]: nsSocketTransportService::RemoveFromPollList [handler=0]
-1318364352[b722fcc0]:   index=0 mActiveCount=1
-1318364352[b722fcc0]:   active=0 idle=0
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = 0 milliseconds
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: nsSocketInputStream::Read [this=9bc7c7e8 count=32768]
-1318364352[b722fcc0]: nsSocketInputStream::CloseWithStatus [this=9bc7c7e8 reason=0]
-1318364352[b722fcc0]: nsSocketInputStream::CloseWithStatus [this=9bc7c7e8 reason=80470002]
-1318364352[b722fcc0]: STS dispatch [9c0fbd88]
-1318364352[b722fcc0]: STS poll iter [0]
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = 0 milliseconds
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: STS poll iter [0]
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = 0 milliseconds
-1318364352[b722fcc0]:     ...returned after 0 milliseconds
-1318364352[b722fcc0]: STS poll iter [1]
-1318364352[b722fcc0]:   calling PR_Poll [active=0 idle=0]
-1318364352[b722fcc0]:     timeout = -1 milliseconds
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrun) fontgroup: [serif] lang: en-us script: 25 len 7 weight: 700 width: 0 style: normal TEXTRUN [[ERROR]] ENDTEXTRUN
-1219901696[b722f1c0]: (textrun) fontgroup: [serif] lang: en-us script: 25 len 7 weight: 700 width: 0 style: normal TEXTRUN [[ERROR]] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnBlurWindow, aWindow=ad5397a0, mLastFocusedWindow=ad5397a0, mIsIMFocused=YES
-1219901696[b722f1c0]: GtkIMModule(9f07b860): Blur, mIsIMFocused=YES
-1219901696[b722f1c0]: GtkIMModule(9f07b860): OnFocusChangeInGecko, aFocus=NO, mCompositionState=NotComposing, mIsIMFocused=NO, mIgnoreNativeCompositionEvent=NO
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [C] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 9 weight: 400 width: 0 style: normal TEXTRUN [ChatZilla] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [I] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 3 weight: 400 width: 0 style: normal TEXTRUN [IRC] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [E] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [Edit] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [V] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [View] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 1 weight: 400 width: 0 style: normal TEXTRUN [H] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 4 weight: 400 width: 0 style: normal TEXTRUN [Help] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 15 weight: 400 width: 0 style: normal TEXTRUN [gatertsertsezrg] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 21 weight: 400 width: 0 style: normal TEXTRUN [Welcome to ChatZilla!] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 8 weight: 400 width: 0 style: normal TEXTRUN [*client*] ENDTEXTRUN
-1219901696[b722f1c0]: (textrunui) fontgroup: ["DejaVu Sans"] lang: en-us script: 25 len 22 weight: 700 width: 0 style: normal TEXTRUN [chat.freenode.net:6697] ENDTEXTRUN
This also happens on a Firefox release from 2010 and on a cZ release from 2011, so not a fault of recent change in them (possibly a recent change in that IRC network). It also happens with /sslserver irc.oftc.net 6697.
The same happens on Thunderbird IM client -- set chat.freenode.net 6697, SSL, disconnect, connect, disconnect, connect, connection will be reset, user will only connect after restarting Thunderbird. 

Going to offline mode and online again does not help either. 

Networking pipelining is off.

SSL 3.0, and TLS 1.0 are ticked in preferences.
I can reproduce this using Comment 0 steps with
User agent: Mozilla/5.0 (Windows NT 5.2; rv:20.0) Gecko/20100101 Firefox/20.0 SeaMonkey/2.17.1
Build identifier: 20130410205058
ChatZilla 0.9.90
on stable wired connection, after pressing reconnect cZ can't reconnect giving reset errors. In log above fail corresponds to
-1318364352[b722fcc0]: nsSocketOutputStream::Write [this=9bc7c808 count=21]
-1318364352[b722fcc0]:   calling PR_Write [count=21]
-1318364352[b722fcc0]:   PR_Write returned [n=-1]
-1318364352[b722fcc0]: ErrorAccordingToNSPR [in=-5961 out=804b0014]
-1318364352[b722fcc0]: nsSocketTransport::OnMsgOutputClosed [this=9bc7c700 reason=804b0014]
Now it needs to find what both values in ErrorAccordingToNSPR mean (not me, at least today)
Brian, do you have any idea what could be causing these SSL socket issues? There's already a reasonable amount of debug info in this bug, if you need us to check anything else, please ask. I suspect it's something to do with the fact that these servers have some kind of support for client certificates, but I'm not sure how I'd go about verifying that hypothesis.
Flags: needinfo?(bsmith)
Sorry for slow responding: I've been in hospital for a week or two, then found a huge lot of email backlog when coming back.

(In reply to :Gijs Kruitbosch from comment #3)
> (In reply to Tony Mechelynck [:tonymec] from comment #2)
> > P.S. I have a networks.txt with an entry for freenode, but as you can see
> > above, all connections happened over SSL.
> 
> Can you try (re)connecting to rajaniemi.freenode.net 6697?

Tried, but I'm not sure how to interpret the results. After /disconnect followed by /reconnect (then hands off the keyboard) I saw:

[Saturday 04:52:27]	[QUIT]	Disconnected from irc://freenode/ (ircs://rajaniemi.freenode.net:6697/). [Reconnect]
[Saturday 04:52:37]	[INFO]	Connecting to ircs://freenode/ (ircs://rajaniemi.freenode.net:6697/)… [Cancel]
	[ERROR]	Connection to irc://freenode/ (ircs://rajaniemi.freenode.net:6697/) reset. [Help] 19 attempts left, reconnecting in 15 seconds. [Cancel]
[Saturday 04:52:52]	[INFO]	Connecting to irc://freenode/ (ircs://chat.eu.freenode.net:6697/)… [Cancel]
[Saturday 04:52:53]	[ERROR]	Connection to irc://freenode/ (ircs://chat.eu.freenode.net:6697/) reset. [Help] 18 attempts left, reconnecting in 15 seconds. [Cancel]
[Saturday 04:53:08]	[INFO]	Connecting to irc://freenode/ (ircs://irc.freenode.net:6697/)… [Cancel]
[Saturday 04:53:09]	===	*** Looking up your hostname...
	===	*** Checking Ident
	===	*** No Ident response
	===	*** Couldn't look up your hostname
[Saturday 04:53:10]	===	Welcome to the freenode Internet Relay Chat Network tonymec
	===	Your host is card.freenode.net[38.229.70.20/6697], running version ircd-seven-1.1.3
	===	This server was created Sun Dec 11 2011 at 22:16:10 UTC

etc.
For one 'connection reset' or 'connection process canceled' message, the b nsSocketTransport::OnMsgOutputClosed breakpoint fires three times. Attached is the stack for each of them.

What more information can I get?
There are so many possible things that could be wrong. Let's find the regression window to narrow it down to a more reasonable search space.

I wouldn't be surprised if Necko or PSM is making some assumption that works for Firefox's built-in use of SSL sockets but which doesn't work for other uses.
Flags: needinfo?(brian)
Keywords: regressionwindow-wanted
(In reply to Tony Mechelynck [:tonymec] from comment #9)
> Sorry for slow responding: I've been in hospital for a week or two, then
> found a huge lot of email backlog when coming back.
> 
> (In reply to :Gijs Kruitbosch from comment #3)
> > (In reply to Tony Mechelynck [:tonymec] from comment #2)
> > > P.S. I have a networks.txt with an entry for freenode, but as you can see
> > > above, all connections happened over SSL.
> > 
> > Can you try (re)connecting to rajaniemi.freenode.net 6697?
> 
> Tried, but I'm not sure how to interpret the results. After /disconnect
> followed by /reconnect (then hands off the keyboard) I saw:
> 
> [Saturday 04:52:27]	[QUIT]	Disconnected from irc://freenode/
> (ircs://rajaniemi.freenode.net:6697/). [Reconnect]
> [Saturday 04:52:37]	[INFO]	Connecting to ircs://freenode/
> (ircs://rajaniemi.freenode.net:6697/)… [Cancel]
> 	[ERROR]	Connection to irc://freenode/ (ircs://rajaniemi.freenode.net:6697/)
> reset. [Help] 19 attempts left, reconnecting in 15 seconds. [Cancel]
> [Saturday 04:52:52]	[INFO]	Connecting to irc://freenode/
> (ircs://chat.eu.freenode.net:6697/)… [Cancel]
> [Saturday 04:52:53]	[ERROR]	Connection to irc://freenode/
> (ircs://chat.eu.freenode.net:6697/) reset. [Help] 18 attempts left,
> reconnecting in 15 seconds. [Cancel]
> [Saturday 04:53:08]	[INFO]	Connecting to irc://freenode/
> (ircs://irc.freenode.net:6697/)… [Cancel]
> [Saturday 04:53:09]	===	*** Looking up your hostname...
> 	===	*** Checking Ident
> 	===	*** No Ident response
> 	===	*** Couldn't look up your hostname
> [Saturday 04:53:10]	===	Welcome to the freenode Internet Relay Chat Network
> tonymec
> 	===	Your host is card.freenode.net[38.229.70.20/6697], running version
> ircd-seven-1.1.3
> 	===	This server was created Sun Dec 11 2011 at 22:16:10 UTC
> 
> etc.

So it looks like with multi-server networks, it works as expected, I think.

What happens when you connect to a specific server only (say, ircs://chat.freenode.net:6697)?
Chatzilla 0.9.69.1 [Firefox 1.0.8/20060410] at Windows XP - The problem still exists. "Connection to ircs://chat.freenode.net:6697/ (ircs://chat.freenode.net:6697/) closed with status 2152398919."
Flags: needinfo?(brian)
Hi, I am willing to help diagnose this problem but first we need to find the first version that stopped working. Could you please tell me the latest version of Firefox where ChatZilla was working correctly and/or the earliest version of Firefox where ChatZilla started having this bug? Then I can probably figure out exactly what change caused it.
Flags: needinfo?(brian) → needinfo?(mozilla)
In c13, this question was already answered: *ancient* versions (5+ years old) still have this issue. 

I did not experience it until earlier this year on a chat server I use daily for 3+ years. Issue may have appeared after server update.
Flags: needinfo?(mozilla) → needinfo?(brian)
OK, sorry, without a regression range there's no way I can work on this.
Flags: needinfo?(brian)
The issue appears to be a little bit intermittent; just try another 20 times and the connection (usually) eventually gets established.
Attached file tcpdump.log — 
TCP dump for 3 connection attempts (unsuccessful, successful, and unsuccessful) after few previous undumped attempts.
Summary: SSL: disconnect, reconnect gives connection reset; all reconnect attempts fail → SSL: disconnect, reconnect gives connection reset; most reconnect attempts fail
Based on comment 6 this appears to be a bug somewhere in core networking or security code.  Moving it to Core :: Networking for now.
Component: ChatZilla → Networking
Product: Other Applications → Core
Summary: SSL: disconnect, reconnect gives connection reset; most reconnect attempts fail → SSL: disconnect, reconnect gives connection reset; most reconnect attempts fail [Chatzilla, Thunderbird chat]
Happens here when trying to reconnect to OFTC.
Unsetting assignee to match the component update. (rginda appears to be the default assignee in the ChatZilla component.)
Assignee: rginda → administration
A second go at setting a reasonable assignee.
Assignee: administration → nobody
I reproduced and investigated this issue (briefly) using a recent seamonkey and the ssltap utility.

On subsequent failing connections, the client application includes a TLS session ticket in the TLS client hello message, and the server disconnects immediately after receiving the client hello message.

Either the TLS server is intolerant of the TLS session ticket extension (likely), or we have a bug in our code (less likely).
Assignee: nobody → nobody
Component: Networking → Libraries
Keywords: regressionwindow-wanted
Product: Core → NSS
Version: Trunk → 3.15.2
I can see the server had sent a new_session_ticket handshake message to the client, of size 160 bytes and ticket_lifetime_hint = unspecified. The session ticket included in the subsequent client hello has the same length.

In other words, the server motivated the client to use TLS session tickets, but then fails to process its own tickets?

(I haven't checked if we make any mistakes when sending the ticket to the server.)
My previous comments were about server chat.freenode.net

In addition I've tested irc.oftc.net, which shows a different issue. In our reconnect attempt, we don't send any TLS session tickets, but the server still disconnects immediately after our client hello message.

We might have not yet found the real cause for the issue.
> Mozilla = No problems. 
Certificate is issued to CN = irc.mozilla.org, O = Mozilla Corporation, 

Hackint – spaceboyz.net = No problems. 
Certificate is issued to CN = spaceboyz.net, O = <not given> and OU = GT84014193
Hackint – irc.yolo.pro = No problems. 
Certificate is issued to CN = irc.yolo.pro, O = Hack.INT IRC network and OU = <not given>
Hackint -  69.31.131.54 = No problems. 
Certificate is issued to CN = chingShih.2600net.org, O = 2600netz and OU = <not given>

> Dalnet – Serveral servers = No reconnect problems. 
CZ can’t connect over SSL to the common address irc.dal.net.  All attempts fail with "status 2153389904" 0x805A1F50.  SSL connects are possible to the specific addresses of each single server in the Dalnet network.  Each server has his own certificate. 
Certificates are issued to CN = irc.dal.net, O = DALnet IRC Network and OU = <differs for each server>

> OFTC – Serveral servers =  Reconnection impossible. 
Different certificates are used and some don’t fit to the CA certificate offered on www.oftc.net. Needs further analysis.

> EsperNet – Several servers = Reconnection impossible. 
After setting the necessary Security Exception on the first connect these server certificates can’t be exported from the Certificate Manager.  Probably they aren’t downloaded.
Certificate is issued to CN = *.esper.net, O = EsperNet and OU = <differs for each server>
Certificate is issued FROM CN = *.esper.net (a wildcard as issuer?)

> Freenode – Several servers = Reconnection impossible. 
A common certificate for all servers in this network. 
Certificate is issued to CN = *.freenode.org, O = <not given> and OU  = Domain Control Validated

*Conclusions:*
Reconnect fails mostly with error status 2153394151 0x804B0047 NS_ERROR_NET_INTERRUPT.  If the new connect is targeted to the IP address of the same server (without DNS resolution) sometimes the error code 2153394151 0x805A2FE7 SSL_ERROR_RX_RECORD_TOO_LONG is shown.

If we have a "One Certificate for One Server" situation reconnection works like a charm.  The server may even have different aliases like concrete.mozilla,org for irc.mozilla,org.  The problems come when certificates with wildcards are used, like CN = *.freenode.org.
I don't think the problem is related to the certificates being used.
Any certificate related problems would be visible on the initial connection attempt, not only on reconnection attempts.

With chat.freenode.net we appear to have problems related to session tickets.

With irc.oftc.net, the server disconnects when the client includes a non-null session ID in the client hello.

With the working mozilla server, the client doesn't send any session ID or session ticket in the reconnection client hello.

It would be interesting to know what server software flavor and versions are being used on the failing servers.
I found that freenode uses heavy round-robin. Even if the application has chosen one of the IP addresses from DNS, and reuses the same IP addresses for reconnections, we might actually get connected to a different server.

The TLS session resumption can only work when connecting to the same server, in my understanding, so it's not a surprise that session resumption fails.

However, what surprises me, is that the server simply disconnects. The server should probably reply with a TLS handshake alert that session resumption isn't possible. This indicates a bad TLS implementation on the server side, IMHO.

I've found an openssl command line, using "s_client -reconnect" that could be used to test that session resumption works correctly. It does so by connecting, then disconnecting, then reconnecting multiple times, which is expected to work without errors. (I used openssl to rule out that it's a problem with our NSS library, and to show that's likely to be a server side issue.)

A command line that uses the most widely used protocol version SSL3 and TLS1.0, only (to rule out TLS protocol version incompatibilities during analysis of this bug report):

openssl s_client -connect SERVER:PORT -no_ssl2 -no_tls1_1 -no_tls1_2 -ssl3 -tls1 -reconnect

Search for "drop connection and then reconnect" in the output.

When running this command against a web server with port 443, I get 5 successful reconnections.

When running against Mozilla's IRC server, I see two successful reconnects, followed by an error. I assume that Mozilla is rate-limiting the connections to prevent attacks on the server.

When performing this against other IRC servers, like chat.freenode.net or irc.oftc.net, I immediately see an error on the first reconnect attempt.

Even when avoiding the DNS round-robin, and choosing one freenode server explicitly, like pratchett.freenode.net / 86.65.39.15 I see failures. I conclude at least some servers (like this one) don't properly implement TLS session resumption at all (unless this is still somehow a cluster of multiple servers, which I don't know).

It would be good to identify which software and versions misbehave in that way.

In order to change Mozilla's client software to be able to reconnect in any scenario, one could disable the session resumption for specific application protocols, e.g. by calling SSL_SetOption(SSL_NO_CACHE, 1). However, that's not a general recommendation, and would have to be somehow coupled to detection of failures.
(In reply to Kai Engert (:kaie) from comment #28)
> I found that freenode uses heavy round-robin. Even if the application has
> chosen one of the IP addresses from DNS, and reuses the same IP addresses
> for reconnections, we might actually get connected to a different server.
> 
> The TLS session resumption can only work when connecting to the same server,
> in my understanding, so it's not a surprise that session resumption fails.
> 
> However, what surprises me, is that the server simply disconnects. The
> server should probably reply with a TLS handshake alert that session
> resumption isn't possible. This indicates a bad TLS implementation on the
> server side, IMHO.
> 
> I've found an openssl command line, using "s_client -reconnect" that could
> be used to test that session resumption works correctly. It does so by
> connecting, then disconnecting, then reconnecting multiple times, which is
> expected to work without errors. (I used openssl to rule out that it's a
> problem with our NSS library, and to show that's likely to be a server side
> issue.)
> 
> A command line that uses the most widely used protocol version SSL3 and
> TLS1.0, only (to rule out TLS protocol version incompatibilities during
> analysis of this bug report):
> 
> openssl s_client -connect SERVER:PORT -no_ssl2 -no_tls1_1 -no_tls1_2 -ssl3
> -tls1 -reconnect
> 
> Search for "drop connection and then reconnect" in the output.
> 
> When running this command against a web server with port 443, I get 5
> successful reconnections.
> 
> When running against Mozilla's IRC server, I see two successful reconnects,
> followed by an error. I assume that Mozilla is rate-limiting the connections
> to prevent attacks on the server.
> 
> When performing this against other IRC servers, like chat.freenode.net or
> irc.oftc.net, I immediately see an error on the first reconnect attempt.
> 
> Even when avoiding the DNS round-robin, and choosing one freenode server
> explicitly, like pratchett.freenode.net / 86.65.39.15 I see failures. I
> conclude at least some servers (like this one) don't properly implement TLS
> session resumption at all (unless this is still somehow a cluster of
> multiple servers, which I don't know).
> 
> It would be good to identify which software and versions misbehave in that
> way.
> 
> In order to change Mozilla's client software to be able to reconnect in any
> scenario, one could disable the session resumption for specific application
> protocols, e.g. by calling SSL_SetOption(SSL_NO_CACHE, 1). However, that's
> not a general recommendation, and would have to be somehow coupled to
> detection of failures.

Kai, thanks a lot for debugging this so extensively! Is the SSL_SetOption bit exposed through XPCOM at all? And/or once a disconnect has taken place, is there any (other) way we could force things to resume correctly, ie force-terminate the connection so the reconnect works "just like a first connect"? ChatZilla is currently all-JS, so it'd be nice if we could figure out how to workaround the bad server behaviour, even if somewhat drastic measures were necessary...
Right now it's not possible to do that from JS.

I'd start with an experimental build to confirm that my theory is correct (that disabling the use of TLS sessions does indeed fix the problem with the given servers).

That would require a change in function nsSSLIOLayerSetOptions to add a call like
  if (SECSuccess != SSL_OptionSet(fd, SSL_NO_CACHE, true)) {
    return NS_ERROR_FAILURE;
  }

If that helps, you would have to find a way to request this property at the time when constructing the TLS socket, by providing a parameter.

But really, I'd appreciate any help to research which server versions (or TLS library protocol versions) are broken so badly, it would be a good idea to reproduce the issue locally with such software, to confirm the brokenness and find potential other workarounds - or to be able to issue a broad statement that given versions are bad.
freenode runs ircd-seven and use openssl for the SSL bits. We use a fair few different Linux distributions as well as various BSD versions across the servers.

A reasonable safe guess would be that our servers run either Debian stable or Debian old-stable however. And we obviously make sure to follow their updates.

Hope this helps a bit in tracking down the problem.
I confirm that the source change proposed in comment 30 does get rid of the issue.
updating summary
Summary: SSL: disconnect, reconnect gives connection reset; most reconnect attempts fail [Chatzilla, Thunderbird chat] → Some SSL/TLS servers disconnect if the client sends valid session resumption state [seen with Chatzilla, Thunderbird chat]
Based on feedback received in the discussion forum, which I agree with, the server is behaving incorrectly.

The broken servers need to be fixed to restart a full handshake, not disconnect, if they receive TLS session state they cannot use to resume/speed up a connection.

http://www.mail-archive.com/dev-tech-crypto@lists.mozilla.org/msg11556.html

Resolving this bug as INVALID.
Assignee: nobody → kaie
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → INVALID
I've been asked about the possibility to use a workaround patch on the client side in Chatzilla.

Unfortunately I cannot think of a patch limited to chatzilla. It would require to introduce additional APIs in PSM and Necko, in order to allow JS application code to request a TLS socket that has session resumption capability disabled.
Another potential workaround:

In addition to the existing security.enable_tls_session_tickets preference,
another boolean preference could be added to PSM like:
  "security.enable_tls_session_cache"
which is set to true by default.

Users who would like to connect to broken servers and are willing to accept the performance penalty on all TLS connections, could set the new pref to disabled.
(In reply to Kai Engert (:kaie) from comment #36)
> In addition to the existing security.enable_tls_session_tickets preference,

This preference was deleted by bug 917049 in October 2013.

It is still present in SM 2.23.  But disabling TLS session tickets alone doesn't solve the reconnection problems to Freenode and OFTC.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: