1493769 - SSL_ERROR_RX_UNEXPECTED_CHANGE_CIPHER error when setting resumption token with SSL_SetResumptionToken

Status: RESOLVED FIXED

(NSS :: Libraries, defect)

Description

[Michal Novotny [:michal]]

Attachment: SSLTRACE=100

This bug is filed for the problem reported in https://bugzilla.mozilla.org/show_bug.cgi?id=1428901#c14. With the patch from bug 1428901, the connection sometimes fails with SSL_ERROR_RX_UNEXPECTED_CHANGE_CIPHER:

#0  0x00007f2074f87c0b in ssl3_HandleChangeCipherSpecs (ss=0x7f2037652000, buf=0x7f2037652290)
    at /mnt/work/opt/moz/hg-inbound-3/security/nss/lib/ssl/ssl3con.c:3169
#1  0x00007f2074f877e2 in ssl3_HandleNonApplicationData (ss=0x7f2037652000, rType=ssl_ct_change_cipher_spec, epoch=0, seqNum=1, databuf=0x7f2037652290) at /mnt/work/opt/moz/hg-inbound-3/security/nss/lib/ssl/ssl3con.c:12339
#2  0x00007f2074f89039 in ssl3_HandleRecord (ss=0x7f2037652000, cText=0x7f20524fdc28)
    at /mnt/work/opt/moz/hg-inbound-3/security/nss/lib/ssl/ssl3con.c:12627
#3  0x00007f2074f9c9ab in ssl3_GatherCompleteHandshake (ss=0x7f2037652000, flags=0)
    at /mnt/work/opt/moz/hg-inbound-3/security/nss/lib/ssl/ssl3gthr.c:527
#4  0x00007f2074fa8983 in SSL_ForceHandshake (fd=0x7f20485e8bb0)
    at /mnt/work/opt/moz/hg-inbound-3/security/nss/lib/ssl/sslsecur.c:399
#5  0x00007f2064334c17 in nsNSSSocketInfo::DriveHandshake() (this=0x7f2036c7b930)
    at /mnt/work/opt/moz/hg-inbound-3/security/manager/ssl/nsNSSIOLayer.cpp:433
#6  0x00007f205de16e97 in mozilla::net::nsHttpConnection::EnsureNPNComplete(nsresult&, unsigned int&) (this=0x7f2036cbf800, aOut0RTTWriteHandshakeValue=@0x7f20524fe0c4: nsresult::NS_OK, aOut0RTTBytesWritten=@0x7f20524fe0c0: 0)
    at /mnt/work/opt/moz/hg-inbound-3/netwerk/protocol/http/nsHttpConnection.cpp:510
#7  0x00007f205de18207 in mozilla::net::nsHttpConnection::OnSocketWritable() (this=0x7f2036cbf800)
    at /mnt/work/opt/moz/hg-inbound-3/netwerk/protocol/http/nsHttpConnection.cpp:1866

Comment 1

[Martin Thomson [:mt:]]

Thanks for opening this.  It appears as though the server believes that it is getting resumption and the client does not.  I'll keep digging as time permits.

Comment 2

[Martin Thomson [:mt:]]

SO this is bizarre.  The ServerHello is absolutely minimal:

   02 00 00 2d 03 03 33 56 c9 19 8a e7 09 3a 7c 84   ...-..3V.....:|.
   2b ef 79 fc 1c 49 d7 74 51 c1 28 7e 2f 71 fb a5   +.y..I.tQ.(~/q..
   97 52 99 a2 c5 2b 00 c0 30 00 00 05 ff 01 00 01   .R...+..0.......
   00                                                .

That is TLS 1.2, no session ID, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, and the renegotiation info extension.  That's ALL.  So it is completely reasonable for the client to assume that the server is not resuming.

The ClientHello has a ticket in it:

   01 00 01 fc 03 03 be 2b ee f0 4d fb 90 52 65 99   .......+..M..Re.
   ec 56 50 70 f0 81 07 9d 84 06 f5 53 42 12 22 b6   .VPp.......SB.".
   ee 76 b9 67 b7 bc 00 00 1e c0 2b c0 2f cc a9 cc   .v.g......+./...
   a8 c0 2c c0 30 c0 0a c0 09 c0 13 c0 14 00 33 00   ..,.0.........3.
   39 00 2f 00 35 00 0a 01 00 01 b5 00 00 00 10 00   9./.5...........
   0e 00 00 0b 77 77 77 2e 72 6f 6f 74 2e 63 7a 00   ....www.root.cz.
   17 00 00 ff 01 00 01 00 00 0a 00 0a 00 08 00 1d   ................
   00 17 00 18 00 19 00 0b 00 02 01 00 00 23 00 c0   .............#..
   e2 6a 6e b0 87 c2 c5 79 11 16 30 78 33 08 8c ba   .jn....y..0x3...
   3a e5 2e 14 05 e3 1d 3a f9 49 e1 5a 94 87 c6 d3   :......:.I.Z....
   4d ef 6a 08 f6 5d 6d c6 23 07 6f 5f 7e a3 37 84   M.j..]m.#.o_~.7.
   9c 52 97 2f e2 c9 3d a5 92 8d e6 32 1e 6d 05 e8   .R./..=....2.m..
   e0 e3 9b 47 e2 78 55 1a 0c d8 27 99 72 2a 87 64   ...G.xU...'.r*.d
   dd 0c 11 2b 50 e9 9b 50 97 bc a1 6a ce 73 9a 22   ...+P..P...j.s."
   26 a6 36 2d 2c 84 36 db ef 75 b8 2c 79 60 af f4   &.6-,.6..u.,y`..
   3c b5 6b 53 a9 5d 8b 02 52 bc 71 e4 df a8 67 39   <.kS.]..R.q...g9
   ef c4 d6 88 34 ab 86 d7 7c d9 59 91 79 62 56 f0   ....4...|.Y.ybV.
   86 fb 5c 29 c0 bf 28 c8 1e c0 a4 87 ac 52 ee 00   ..\)..(......R..
   57 00 68 74 fa 3e 3b 20 a9 8b 9d 6b 3a 35 af 77   W.ht.>; ...k:5.w
   a6 91 89 33 2a 30 22 05 21 87 1f 38 2f f3 dc c8   ...3*0".!..8/...
   00 10 00 0e 00 0c 02 68 32 08 68 74 74 70 2f 31   .......h2.http/1
   2e 31 00 05 00 05 01 00 00 00 00 00 0d 00 18 00   .1..............
   16 04 03 05 03 06 03 08 04 08 05 08 06 04 01 05   ................
   01 06 01 02 03 02 01 00 1c 00 02 40 00 00 15 00   ...........@....
   7f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................
   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00   ................

But it doesn't have a session_id.  Maybe that is it.  More investigation required - I need to look at the specs - but it looks like a server issue here.  Is this problem common?  Or is it just www.root.cz?

Comment 3

[Martin Thomson [:mt:]]

The crazy thing here is that we aren't generating a new session ID as a result of this.  Which is legitimate, but probably unexpected on the server side.  The server does this weird thing where it assumes that it is doing a session-ID-based resumption and we get what you see there.

More digging will be required to find out what software is running on this server.  It might be worth checking whether setting the session ID fixes the issue.

Comment 4

[Martin Thomson [:mt:]]

That's it, we need to generate a new random session ID in NSS.  It's a simple fix, but it will take a little time to get around to it.

Comment 5

[Michal Novotny [:michal]]

(In reply to Martin Thomson [:mt:] from comment #2)
> But it doesn't have a session_id.  Maybe that is it.  More investigation
> required - I need to look at the specs - but it looks like a server issue
> here.  Is this problem common?  Or is it just www.root.cz?

I can reproduce it on google.com or mozilla.org too, but not as reliable as on root.cz, so the SSLTRACE log is huge. Do you want it?

Comment 6

[Martin Thomson [:mt:]]

Nah, I know exactly how to fix it.  The fix is simple enough, I just have a ton of work to get through.

Comment 7

[Martin Thomson [:mt:]]

Attachment: Bug 1493769 - Set session_id for external resumption tokens, r?franziskus

This also includes some cleanup that I performed when looking into this.

It turns out that the hacks that we were using for managing the reference count
on sids was unnecessary.  Daiki added a much neater solution in D7493 that I
stole.

The error handling in SSLExp_SetResumptionToken looks nicer after a
spring-clean too.

Comment 8

[Martin Thomson [:mt:]]

Sorry this took so long... https://hg.mozilla.org/projects/nss/rev/4ae3cc850070c1ab33b8d241b3c433141fbd7175