1417331 - Key log support for early exporter master secret

Status: RESOLVED FIXED

(NSS :: Libraries, defect)

Description

[Peter Wu]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:56.0) Gecko/20100101 Firefox/56.0
Build ID: 20171027085204

Steps to reproduce:

Run the key log unit tests:

HOST=localhost DOMSUF=localdomain NSS_CYCLES=standard NSS_TESTS='gtests ssl_gtests' tests/all.sh

Future runs (for faster testing):

ninja -C out/Debug && (cd ../tests_results/security/localhost.1/ssl_gtests &&
../../../../dist/Debug/bin/ssl_gtest --gtest_filter=KeyLogFileTLS13/KeyLogFileTest\*)


Actual results:

No key log file was created.
After fixing the tests, "EARLY_EXPORTER_SECRET" is missing.
After adding the label, the Client Random field is all zeroes.


Expected results:

EARLY_EXPORTER_SECRET should be logged such that it can be used to decrypt 0-RTT QUIC traffic for debugging.

Comment 1

[Peter Wu]

Attachment: 1-Bug_1417331___fix_key_log_unit_tests.patch

This patch makes the unit test functional again.

Comment 2

[Peter Wu]

Attachment: obvious-early-exporter.patch

This "obvious" patch to add support for exporting the early exporter master secret fails the test, somehow it finds three different client randoms. Inspecting ../test_results/security/localhost.1/ssl_gtests/keylog.txt:

EARLY_EXPORTER_SECRET 0000000000... 76c291efb7..
CLIENT_EARLY_TRAFFIC_SECRET eb705a3a93... 4067dc8152...
EARLY_EXPORTER_SECRET eb705a3a93... 76c291efb7...
CLIENT_EARLY_TRAFFIC_SECRET eb705a3a93... 4067dc8152...

uhh... so the client random is not initialized when the early export secret is calculated? Is that on purpose?

Comment 3

[Martin Thomson [:mt:]]

Comment on attachment 8928435 [details] [diff] [review]
1-Bug_1417331___fix_key_log_unit_tests.patch

Review of attachment 8928435 [details] [diff] [review]:
-----------------------------------------------------------------

Phabricator would be a better choice.

::: gtests/ssl_gtest/ssl_keylog_unittest.cc
@@ +23,4 @@
>      (void)remove(keylog_file_path.c_str());
>      std::ostringstream sstr;
>      sstr << "SSLKEYLOGFILE=" << keylog_file_path;
> +    PR_SetEnv(strdup(sstr.str().c_str()));

Rather than use strdup here and leak, can you instead copy to a static array?  We don't run any of this in parallel, so concurrent access shouldn't be an issue.

Comment 4

[Peter Wu]

Attachment: 1-Bug_1417331___fix_key_log_unit_tests-v2.patch

v2: using a const string instead, this is still readable and avoid the leak.

Comment 5

[Martin Thomson [:mt:]]

Comment on attachment 8928785 [details] [diff] [review]
1-Bug_1417331___fix_key_log_unit_tests-v2.patch

Review of attachment 8928785 [details] [diff] [review]:
-----------------------------------------------------------------

I put this up on try and we'll see how it works out.

https://treeherder.mozilla.org/#/jobs?repo=nss-try&revision=ec6937fcfe002a17f06b871b42c341446021d4e8

Comment 6

[Martin Thomson [:mt:]]

https://hg.mozilla.org/projects/nss/rev/36dc2b60c1f61f2c3bed38eced382333e966f90b

Comment 7

[Martin Thomson [:mt:]]

Oops, I just realized that we didn't do anything about the actual patch here.  Is this still something that you intend to pursue Peter?

As for the obvious patch, the client random should be set when the ClientHello is sent, which precedes the generation of early secrets and all that business.

Comment 8

[Martin Thomson [:mt:]]

Ahh, the early exporter was being created before the random.  A little bit of tweaking is necessary here.

Comment 9

[Kai Engert [:KaiE:]]

With this patch checked in, when built with the NSS_FORCE_FIPS=1 configuration, several tests are failing (as can be seen on our buildbot):

ssl_gtest.sh: #8335: 'KeyLogFileDTLS12/KeyLogFileTest: KeyLogFile/0 (1, 770)' - FAILED
ssl_gtest.sh: #8336: 'KeyLogFileDTLS12/KeyLogFileTest: KeyLogFile/1 (1, 771)' - FAILED
ssl_gtest.sh: #8337: 'KeyLogFileTLS12/KeyLogFileTest: KeyLogFile/0 (0, 769)' - FAILED
ssl_gtest.sh: #8338: 'KeyLogFileTLS12/KeyLogFileTest: KeyLogFile/1 (0, 770)' - FAILED
ssl_gtest.sh: #8339: 'KeyLogFileTLS12/KeyLogFileTest: KeyLogFile/2 (0, 771)' - FAILED
ssl_gtest.sh: #8340: 'KeyLogFileTLS13/KeyLogFileTest: KeyLogFile/0 (0, 772)' - FAILED

(Maybe we should consider to have at least one of the Mozilla test systems use that build configuration.)

Comment 10

[Kai Engert [:KaiE:]]

Additional log output:

[ RUN      ] KeyLogFileDTLS12/KeyLogFileTest.KeyLogFile/0
[  DEATH   ] Version: DTLS 1.0
[  DEATH   ] server: Changing state from INIT to CONNECTING
[  DEATH   ] client: Changing state from INIT to CONNECTING
[  DEATH   ] server: Handshake success
[  DEATH   ] server: Changing state from CONNECTING to CONNECTED
[  DEATH   ] client: Handshake success
[  DEATH   ] client: Changing state from CONNECTING to CONNECTED
[  DEATH   ] Connected with version 770 cipher suite TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA
[  DEATH   ] 
[  DEATH   ] ssl_keylog_unittest.cc:95:: Caught std::exception-derived exception escaping the death test statement. Exception message: ssl_keylog_unittest.cc:47: Failure
[  DEATH   ] Value of: client_randoms.size()
[  DEATH   ]   Actual: 0
[  DEATH   ] Expected: 1U
[  DEATH   ] Which is: 1
[  DEATH   ] 
[  FAILED  ] KeyLogFileDTLS12/KeyLogFileTest.KeyLogFile/0, where GetParam() = (1, 770) (134 ms)


Full log here: https://bot.nss-crypto.org:8011/builders/fedora-x64-OPT/builds/1218/steps/shell/logs/stdio

Comment 11

[Peter Wu]

A possible reason for that failure is that NSS gets initialized before the test is invoked. Once initialized, it won't use the environment variable that is set in the child process of the "death test" and thus the file is not written.

The test could either be skipped in case of NSS_FORCE_FIPS (meh) or a new gtest binary could be added, specifically for testing the behavior with SSLKEYLOGFILE (meh...). Thoughts?

Comment 12

[Martin Thomson [:mt:]]

I think that we want to skip this if FIPS is enabled.  What is most likely happening here (which I will try to confirm), is that FIPS is preventing us from accessing the symmetric key contents.  That's expected with FIPS.

Comment 13

[Martin Thomson [:mt:]]

Landed: https://hg.mozilla.org/projects/nss/rev/7c9e5bd3d8fe33be7bc0ebfe74ee3934e2fc64f4

Comment 14

[Kai Engert [:KaiE:]]

Thanks for working on this failure, but it's not fixed yet. On buildbot we still get the same failures reported in comment 47 and comment 48.

(In reply to Martin Thomson [:mt:] from comment #13)
> Landed:
> https://hg.mozilla.org/projects/nss/rev/
> 7c9e5bd3d8fe33be7bc0ebfe74ee3934e2fc64f4

Which strategy did you try in this commit? It seems you didn't disable the tests. Should we?

Comment 15

[Kai Engert [:KaiE:]]

Also, we have an open work item for testing in FIPS mode. We had recently discovered that our environment variables are inconsistent between "gyp" and "make" builds. It's difficult to detect if the tests should assume FIPS enabled or FIPS disabled. The TODO bug is bug 1409516. So, if we want different testing behavior based on FIPS mode, we'd need a fix for bug 1409516.

Comment 16

[Martin Thomson [:mt:]]

So that commit doesn't change anything.  These tests should not have suddenly stopped working as a result of that commit.  It's the commit that added key log tests that would be the offending one. bc6d9e5391da is where I can trace this to (apologies to peter, that's his code, not mine - an operator issue with phabricator, I believe).

I'm having real trouble getting this test to fail on my machine.  I build with NSS_FORCE_FIPS=1, I set FIPS mode on the database, and still the tests pass.  Which of the many options do I have to set to get the tests to run in a manner consistent with the failing build?

Comment 17

[Kai Engert [:KaiE:]]

Apparently it's happening only in optimized builds, you'll have to set BUILD_OPT=1

I'm now trying to reproduce locally, too.

Comment 18

[Kai Engert [:KaiE:]]

The tests are failing in optimized builds, because we disallow the key log file in optimized builds.

nss/lib/ssl/Makefile contains:
  NSS_ALLOW_SSLKEYLOGFILE ?= $(if $(BUILD_OPT),0,1)

So the solution is to disable these tests in optimized builds.

Comment 19

[Kai Engert [:KaiE:]]

Attachment: 1417331-fix-tests.patch

Comment 20

[Martin Thomson [:mt:]]

Comment on attachment 8933595 [details] [diff] [review]
1417331-fix-tests.patch

Review of attachment 8933595 [details] [diff] [review]:
-----------------------------------------------------------------

So obvious, thanks Kai.

Comment 21

[Kai Engert [:KaiE:]]

Comment on attachment 8933595 [details] [diff] [review]
1417331-fix-tests.patch

https://hg.mozilla.org/projects/nss/rev/0bd865cf27a7

Comment 22

[Kai Engert [:KaiE:]]

Another question:

Why didn't the taskcluster builds in optimized mode fail, too?

Comment 23

[Kai Engert [:KaiE:]]

(In reply to Kai Engert (:kaie:) from comment #22)
> Why didn't the taskcluster builds in optimized mode fail, too?

Because the gyp build explicitly always always allows it, independencly of build type:

lib/ssl/ssl.gyp:
  'target_defaults': {
    'defines': [
      'NSS_ALLOW_SSLKEYLOGFILE=1'
    ]
  },

That's a difference between gyp and make builds.

Should gyp build disable the keylogfile in optimized builds?

Comment 24

[Kai Engert [:KaiE:]]

Another insufficiency with taskcluster:

Although it executes NSS "make" builds, it didn't show the issue with the optimized make builds. I conclude that taskcluster executeds "make debug" builds, only. Can we enhance taskcluster to run "make optimized" builds, too?

Comment 25

[Kai Engert [:KaiE:]]

(In reply to Kai Engert (:kaie:) from comment #24)
> Another insufficiency with taskcluster:
> 
> Although it executes NSS "make" builds, it didn't show the issue with the
> optimized make builds. I conclude that taskcluster executeds "make debug"
> builds, only. Can we enhance taskcluster to run "make optimized" builds, too?

filed bug 1422848 for this one

Comment 26

[Kai Engert [:KaiE:]]

(In reply to Kai Engert (:kaie:) from comment #23)
> Should gyp build disable the keylogfile in optimized builds?

Let's handle that in bug 1422854.

Comment 27

[Phabricator Automation]

Comment on attachment 8932798 [details]
Bug 1417331 - Early exporters for TLS 1.3, r?lekensteyn

Peter Wu has approved the revision.

https://phabricator.services.mozilla.com/D287