runtime: Some delay-loaded system DLLs fail to load on Windows Server 2016

[jblazquez]

1. What version of Go are you using (go version)?

go version go1.6.2 windows/amd64

2. What operating system and processor architecture are you using (go env)?

Windows Server 2016 Technical Preview 5 (x64)

3. What did you do?

Compile the example code for rand.Read:

> type test.go

package main

import (
        "bytes"
        "crypto/rand"
        "fmt"
)

func main() {
        c := 10
        b := make([]byte, c)
        _, err := rand.Read(b)
        if err != nil {
                fmt.Println("error:", err)
                return
        }
        // The slice should now contain random bytes instead of only zeroes.
        fmt.Println(bytes.Equal(b, make([]byte, c)))
}

> go build test.go

And then try to run it:

> test.exe
error: CryptAcquireContext: The specified procedure could not be found.

4. What did you expect to see?

Expected the correct output for the program: false.

5. What did you see instead?

An error returned from rand.Read regarding CryptAcquireContext. Other entry points from other DLLs are also affected. This breaks a large amount of functionality, e.g. go get for SSH remotes.

Additional information

I traced this to a problem somewhere in the Windows loader when trying to resolve DLL paths for certain delay-loaded libraries. I don't know if this is a Go bug or a Windows bug.

In the example above the problem is caused when the first call to advapi32!CryptAcquireContextW in rand.Read triggers the delay load of cryptsp.dll to resolve that forwarded export (advapi32.dll doesn't implement that API, cryptsp.dll does). For some reason this delay load fails and all forwarded crypto entry points in advapi32.dll are then replaced with a stub that always returns an error.

The reason for the delay load failure is mysterious, but it's somehow related to LdrpComputeLazyDllPath in ntdll.dll. You can see some relevant error messages from the Windows loader if you turn on loader snaps via gflags for the test.exe binary, as explained here:

1. Install the Windows 10 SDK so you get gflags and the debuggers.
2. Enable loader snaps: "C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\gflags.exe" -i test.exe +sls
3. Run test.exe under the debugger to dump the loader debug output: "C:\Program Files (x86)\Windows Kits\10\Debuggers\x64\cdb.exe" -c "g; q" test.exe > test.txt

You should get some very verbose output. Now grep for LdrpComputeLazyDllPath and you should see two occurrences, one for tsappcmp.dll which works fine and then one for cryptsp.dll which doesn't:

> type test.txt | grep LdrpComputeLazyDllPath -B 5 -A 6

1e9c:147c @ 103841203 - LdrLoadDll - ENTER: DLL name: tsappcmp.dll
1e9c:147c @ 103841203 - LdrpLoadDllInternal - ENTER: DLL name: tsappcmp.dll
1e9c:147c @ 103841203 - LdrpFindKnownDll - ENTER: DLL name: tsappcmp.dll
1e9c:147c @ 103841203 - LdrpFindKnownDll - RETURN: Status: 0xc0000135
1e9c:147c @ 103841203 - LdrpSearchPath - ENTER: DLL name: tsappcmp.dll
1e9c:147c @ 103841203 - LdrpComputeLazyDllPath - INFO: DLL search path computed: C:\Windows\SYSTEM32
1e9c:147c @ 103841203 - LdrpResolveDllName - ENTER: DLL name: C:\Windows\SYSTEM32\tsappcmp.dll
1e9c:147c @ 103841203 - LdrpResolveDllName - RETURN: Status: 0x00000000
1e9c:147c @ 103841203 - LdrpSearchPath - RETURN: Status: 0x00000000
1e9c:147c @ 103841203 - LdrpMapViewOfSection - ENTER: DLL name: C:\Windows\SYSTEM32\tsappcmp.dll
ModLoad: 00007ffb`1bbf0000 00007ffb`1bc0a000   C:\Windows\SYSTEM32\tsappcmp.dll
1e9c:147c @ 103841203 - LdrpMapViewOfSection - RETURN: Status: 0x00000000

---

1e9c:147c @ 103842156 - LdrpGetProcedureAddress - INFO: Locating procedure "LoadLibraryExW" by name
1e9c:147c @ 103842156 - LdrpLoadDllInternal - ENTER: DLL name: CRYPTSP.dll
1e9c:147c @ 103842156 - LdrpFindKnownDll - ENTER: DLL name: CRYPTSP.dll
1e9c:147c @ 103842171 - LdrpFindKnownDll - RETURN: Status: 0xc0000135
1e9c:147c @ 103842171 - LdrpSearchPath - ENTER: DLL name: CRYPTSP.dll
1e9c:147c @ 103842171 - LdrpComputeLazyDllPath - INFO: DLL search path computed: ??
1e9c:147c @ 103842171 - LdrpResolveDllName - ENTER: DLL name: ??\CRYPTSP.dll
1e9c:147c @ 103842171 - LdrpResolveDllName - RETURN: Status: 0xc0000135
1e9c:147c @ 103842171 - LdrpSearchPath - RETURN: Status: 0xc0000135
1e9c:147c @ 103842171 - LdrpProcessWork - ERROR: Unable to load DLL: "CRYPTSP.dll", Parent Module: "C:\Windows\system32\ADVAPI32.dll", Status: 0xc0000135
1e9c:147c @ 103842171 - LdrpLoadDllInternal - RETURN: Status: 0xc0000135
1e9c:147c @ 103842171 - LdrpRedirectDelayloadFailure - ERROR: Failed to find export CRYPTSP.dll!CryptAcquireContextW (Ordinal:0) in "ADVAPI32.dll"  0xc0000135

The critical lines are:

1e9c:147c @ 103842171 - LdrpComputeLazyDllPath - INFO: DLL search path computed: ??
1e9c:147c @ 103842171 - LdrpResolveDllName - ENTER: DLL name: ??\CRYPTSP.dll

For some reason the loader is unable to compute the DLL path for cryptsp.dll, but it can do so fine for other DLLs.

It's not just cryptsp.dll that fails to load. There are at least 4 other delay-loaded DLLs with the same problem (iphlpapi.dll, userenv.dll, netapi32.dll, secur32.dll). You can see these other failed loads by running the Go unit tests:

> cd %GOROOT%\src
> run.bat
##### Testing packages.
ok      archive/tar 2.156s
ok      archive/zip 1.781s
ok      bufio   2.031s
ok      bytes   1.641s
ok      compress/bzip2  1.078s
ok      compress/flate  3.780s
ok      compress/gzip   1.391s
ok      compress/lzw    0.392s
ok      compress/zlib   1.344s
ok      container/heap  0.578s
ok      container/list  0.594s
ok      container/ring  0.328s
ok      crypto/aes  1.188s
--- FAIL: ExampleNewCTR (0.00s)
panic: CryptAcquireContext: The specified procedure could not be found. [recovered]
    panic: CryptAcquireContext: The specified procedure could not be found.

goroutine 1 [running]:
panic(0x59a4e0, 0xc082002e60)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.runExample.func2(0xecec5ad98, 0xc010d8236c, 0x6ccce0, 0xc08202c068, 0xc08202c010, 0xc082010d20, 0x5dbf00, 0xd, 0x627640, 0x5e16c0, ...)
    C:/Go/src/testing/example.go:93 +0x401
panic(0x59a4e0, 0xc082002e60)
    C:/Go/src/runtime/panic.go:443 +0x4f7
crypto/cipher_test.ExampleNewCTR()
    C:/Go/src/crypto/cipher/example_test.go:207 +0x221
testing.runExample(0x5dbf00, 0xd, 0x627640, 0x5e16c0, 0xf, 0x0)
    C:/Go/src/testing/example.go:98 +0x3de
testing.RunExamples(0x6276d8, 0x6c9980, 0x4, 0x4, 0x1)
    C:/Go/src/testing/example.go:36 +0x31b
testing.(*M).Run(0xc082037ee8, 0x1)
    C:/Go/src/testing/testing.go:516 +0xc4
main.main()
    crypto/cipher/_test/_testmain.go:104 +0x11e
FAIL    crypto/cipher   2.141s
ok      crypto/des  1.172s
--- FAIL: TestSignAndVerify (0.00s)
    dsa_test.go:17: 0: error signing: CryptAcquireContext: The specified procedure could not be found.
FAIL
FAIL    crypto/dsa  0.391s
--- FAIL: TestKeyGeneration (0.00s)
    ecdsa_test.go:27: p224: error: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestSignAndVerify (0.00s)
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x1 addr=0x0 pc=0x483002]

goroutine 7 [running]:
panic(0x5d19a0, 0xc082006110)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.tRunner.func1(0xc082080090)
    C:/Go/src/testing/testing.go:467 +0x199
panic(0x5d19a0, 0xc082006110)
    C:/Go/src/runtime/panic.go:443 +0x4f7
crypto/ecdsa.Sign(0x9844f0, 0xc0820065d0, 0x0, 0xc082006718, 0x7, 0x8, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/crypto/ecdsa/ecdsa.go:152 +0x8e2
crypto/ecdsa.testSignAndVerify(0xc082080090, 0x984600, 0xc08200e3f0, 0x60b1c8, 0x4)
    C:/Go/src/crypto/ecdsa/ecdsa_test.go:84 +0xf2
crypto/ecdsa.TestSignAndVerify(0xc082080090)
    C:/Go/src/crypto/ecdsa/ecdsa_test.go:101 +0x63
testing.tRunner(0xc082080090, 0x70b678)
    C:/Go/src/testing/testing.go:473 +0x9f
created by testing.RunTests
    C:/Go/src/testing/testing.go:582 +0x899
FAIL    crypto/ecdsa    0.672s
--- FAIL: TestMarshal (0.00s)
    elliptic_test.go:460: CryptAcquireContext: The specified procedure could not be found.
FAIL
FAIL    crypto/elliptic 1.375s
ok      crypto/hmac 0.686s
ok      crypto/md5  1.391s
--- FAIL: TestRead (0.00s)
    rand_test.go:22: ReadFull(buf) = 0, CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestReadEmpty (0.00s)
    rand_test.go:37: Read(make([]byte, 0)) = 0, CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestPrimeSmall (0.00s)
    util_test.go:18: Can't generate 2-bit prime: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestInt (0.00s)
    util_test.go:41: Can't generate random value: <nil>, CryptAcquireContext: The specified procedure could not be found.
--- FAIL: ExampleRead (0.00s)
got:
error: CryptAcquireContext: The specified procedure could not be found.
want:
false
FAIL
FAIL    crypto/rand 1.891s
ok      crypto/rc4  1.094s
--- FAIL: TestEncryptPKCS1v15 (0.00s)
    pkcs1v15_test.go:88: error encrypting: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestEncryptPKCS1v15DecrypterSessionKey (0.00s)
    pkcs1v15_test.go:156: #0: error decrypting: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestNonZeroRandomBytes (0.00s)
    pkcs1v15_test.go:174: returned error: CryptAcquireContext: The specified procedure could not be found.
    pkcs1v15_test.go:178: Zero octet found
--- FAIL: TestShortSessionKey (0.00s)
    pkcs1v15_test.go:262: Failed to encrypt short message: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestPSSSigning (0.00s)
    pss_test.go:224: #0: error while signing: CryptAcquireContext: The specified procedure could not be found.
    pss_test.go:224: #1: error while signing: CryptAcquireContext: The specified procedure could not be found.
    pss_test.go:224: #2: error while signing: CryptAcquireContext: The specified procedure could not be found.
    pss_test.go:224: #3: error while signing: CryptAcquireContext: The specified procedure could not be found.
    pss_test.go:224: #4: error while signing: CryptAcquireContext: The specified procedure could not be found.
    pss_test.go:224: #5: error while signing: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestKeyGeneration (0.00s)
    rsa_test.go:24: failed to generate key
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x0 pc=0x48f3b8]

goroutine 49 [running]:
panic(0x5bac40, 0xc082006110)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.tRunner.func1(0xc082522f30)
    C:/Go/src/testing/testing.go:467 +0x199
panic(0x5bac40, 0xc082006110)
    C:/Go/src/runtime/panic.go:443 +0x4f7
crypto/rsa.TestKeyGeneration(0xc082522f30)
    C:/Go/src/crypto/rsa/rsa_test.go:26 +0xe8
testing.tRunner(0xc082522f30, 0x6e95e8)
    C:/Go/src/testing/testing.go:473 +0x9f
created by testing.RunTests
    C:/Go/src/testing/testing.go:582 +0x899
FAIL    crypto/rsa  1.969s
ok      crypto/sha1 0.485s
ok      crypto/sha256   0.841s
ok      crypto/sha512   0.844s
ok      crypto/subtle   0.297s
--- FAIL: TestClientResumption (0.00s)
    handshake_client_test.go:445: Handshake: handshake failed: remote error: internal error
panic: test timed out after 6m0s

goroutine 97 [running]:
panic(0x67b4c0, 0xc0825cc050)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.startAlarm.func1()
    C:/Go/src/testing/testing.go:725 +0x152
created by time.goFunc
    C:/Go/src/time/sleep.go:129 +0x41

goroutine 1 [chan receive, 5 minutes]:
testing.RunTests(0x7be5a0, 0x8bf120, 0x40, 0x40, 0x0)
    C:/Go/src/testing/testing.go:583 +0x8d9
testing.(*M).Run(0xc082325ef8, 0xc08207de60)
    C:/Go/src/testing/testing.go:515 +0x88
main.main()
    crypto/tls/_test/_testmain.go:182 +0x11e

goroutine 82 [semacquire, 5 minutes]:
sync.runtime_Syncsemacquire(0xc0820876f8)
    C:/Go/src/runtime/sema.go:241 +0x20f
sync.(*Cond).Wait(0xc0820876e8)
    C:/Go/src/sync/cond.go:63 +0xa2
io.(*pipe).write(0xc082087680, 0xc08231cb8a, 0x5, 0x5, 0x0, 0x0, 0x0)
    C:/Go/src/io/pipe.go:94 +0x241
io.(*PipeWriter).Write(0xc08202c158, 0xc08231cb8a, 0x5, 0x5, 0x0, 0x0, 0x0)
    C:/Go/src/io/pipe.go:161 +0x57
crypto/tls.TestServerSelectingUnconfiguredCipherSuite(0xc0825c85a0)
    C:/Go/src/crypto/tls/handshake_client_test.go:689 +0x9ce
testing.tRunner(0xc0825c85a0, 0x8bf2d0)
    C:/Go/src/testing/testing.go:473 +0x9f
created by testing.RunTests
    C:/Go/src/testing/testing.go:582 +0x899
FAIL    crypto/tls  361.078s
--- FAIL: TestEncrypt (0.00s)
    pem_decrypt_test.go:43: test 0. 1
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
    pem_decrypt_test.go:43: test 1. 2
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
    pem_decrypt_test.go:43: test 2. 3
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
    pem_decrypt_test.go:43: test 3. 4
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
    pem_decrypt_test.go:43: test 4. 5
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
    pem_decrypt_test.go:43: test 5. 3
    pem_decrypt_test.go:51: encrypt:  x509: cannot generate IV: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestSystemVerify (0.40s)
    verify_test.go:358: #1: unexpected error: winapi error #3221225594
    verify_test.go:367: #1: wanted 1 chains, got 0
    verify_test.go:358: #2: unexpected error: winapi error #3221225594
    verify_test.go:367: #2: wanted 1 chains, got 0
    verify_test.go:242: #3: error was not a HostnameError: winapi error #3221225594
--- FAIL: TestCreateSelfSignedCertificate (0.00s)
    x509_test.go:325: Failed to generate ECDSA key: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestUnknownCriticalExtension (0.00s)
    x509_test.go:507: Failed to generate ECDSA key: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestCRLCreation (0.14s)
    x509_test.go:793: error creating CRL: CryptAcquireContext: The specified procedure could not be found.
    x509_test.go:798: error reparsing CRL: asn1: syntax error: sequence truncated
--- FAIL: TestImports (2.39s)
    x509_test.go:866: failed to run x509_test_import.go: exit status 1
--- FAIL: TestCreateCertificateRequest (0.00s)
    x509_test.go:885: Failed to generate ECDSA key: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestCertificateRequestOverrides (0.00s)
    x509_test.go:962: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestMaxPathLen (0.00s)
    x509_test.go:1138: failed to create certificate: CryptAcquireContext: The specified procedure could not be found.
FAIL
FAIL    crypto/x509 3.750s
ok      database/sql    0.906s
ok      database/sql/driver 0.719s
ok      debug/dwarf 0.906s
ok      debug/elf   0.954s
ok      debug/gosym 1.312s
ok      debug/macho 0.719s
ok      debug/pe    1.610s
ok      debug/plan9obj  0.500s
ok      encoding/ascii85    1.016s
ok      encoding/asn1   1.000s
ok      encoding/base32 0.892s
ok      encoding/base64 0.766s
ok      encoding/binary 0.938s
ok      encoding/csv    0.484s
ok      encoding/gob    0.782s
ok      encoding/hex    0.423s
ok      encoding/json   1.906s
ok      encoding/pem    0.456s
ok      encoding/xml    0.501s
ok      errors  0.844s
ok      expvar  0.938s
ok      flag    1.016s
ok      fmt 0.845s
ok      go/ast  0.781s
ok      go/build    1.922s
ok      go/constant 1.453s
ok      go/doc  1.484s
ok      go/format   0.875s
ok      go/internal/gccgoimporter   0.984s
ok      go/internal/gcimporter  1.610s
ok      go/parser   1.094s
ok      go/printer  1.564s
ok      go/scanner  0.856s
ok      go/token    0.406s
ok      go/types    2.532s
ok      hash/adler32    0.326s
ok      hash/crc32  0.952s
ok      hash/crc64  0.938s
ok      hash/fnv    0.500s
ok      html    0.328s
ok      html/template   1.031s
ok      image   1.453s
ok      image/color 0.453s
ok      image/draw  0.797s
ok      image/gif   1.391s
ok      image/jpeg  1.766s
ok      image/png   1.875s
ok      index/suffixarray   0.467s
ok      internal/golang.org/x/net/http2/hpack   0.688s
ok      internal/singleflight   0.344s
--- FAIL: TestGetMUIStringValue (0.00s)
    registry_test.go:718: GetMUIStringValue: MUI_Std: Got "Pacific Standard Time", want "@tzres.dll,-212"
    registry_test.go:718: GetMUIStringValue: MUI_Dlt: Got "Pacific Daylight Time", want "@tzres.dll,-211"
FAIL
FAIL    internal/syscall/windows/registry   0.781s
ok      internal/trace  0.628s
ok      io  1.110s
ok      io/ioutil   1.234s
ok      log 0.672s
ok      math    0.656s
ok      math/big    1.250s
ok      math/cmplx  1.127s
ok      math/rand   0.828s
ok      mime    0.563s
panic: CryptAcquireContext: The specified procedure could not be found.

goroutine 1 [running]:
panic(0x5fddc0, 0xc082002c00)
    C:/Go/src/runtime/panic.go:481 +0x3f4
mime/multipart.randomBoundary(0x0, 0x0)
    C:/Go/src/mime/multipart/writer.go:76 +0xef
mime/multipart.NewWriter(0x9f8808, 0xc08200e0e0, 0x787478)
    C:/Go/src/mime/multipart/writer.go:29 +0x23
mime/multipart.roundTripParseTest(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/mime/multipart/multipart_test.go:798 +0xdf9
mime/multipart.init()
    C:/Go/src/mime/multipart/multipart_test.go:700 +0x1ddd
main.init()
    mime/multipart/_test/_testmain.go:94 +0x51
FAIL    mime/multipart  0.500s
ok      mime/quotedprintable    1.859s
panic: Failed to load iphlpapi.dll: The specified module could not be found.

goroutine 1 [running]:
panic(0x6e3b00, 0xc082062cc0)
    C:/Go/src/runtime/panic.go:481 +0x3f4
syscall.(*LazyProc).mustFind(0xc082005fb0)
    C:/Go/src/syscall/dll_windows.go:280 +0x6a
syscall.(*LazyProc).Addr(0xc082005fb0, 0x0)
    C:/Go/src/syscall/dll_windows.go:287 +0x28
internal/syscall/windows.GetAdaptersAddresses(0x1000000000, 0x0, 0xc08207c000, 0xc082079374, 0x0, 0x0)
    C:/Go/src/internal/syscall/windows/zsyscall_windows.go:23 +0x42
net.adapterAddresses(0x0, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/net/interface_windows.go:42 +0xf3
net.interfaceTable(0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/net/interface_windows.go:67 +0x5a
net.Interfaces(0x0, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/net/interface.go:89 +0x4e
net.loopbackInterface(0x7078e0)
    C:/Go/src/net/interface_test.go:17 +0x2b
net.setupTestData()
    C:/Go/src/net/main_test.go:94 +0x157b
net.TestMain(0xc082079ed8)
    C:/Go/src/net/main_test.go:47 +0x1f
main.main()
    net/_test/_testmain.go:396 +0x11b
FAIL    net 0.750s
--- FAIL: TestReadResponseCloseInMiddle (0.03s)
    response_test.go:568: on test chunked=true, compressed=true: rand.Reader ReadFull: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33764: remote error: internal error
--- FAIL: TestClientHead_h2 (0.00s)
    client_test.go:94: Head https://127.0.0.1:33763: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33778: remote error: internal error
--- FAIL: TestStreamingGet_h2 (0.00s)
    client_test.go:531: Get https://127.0.0.1:33777: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestClientInsecureTransport (0.00s)
    client_test.go:623: insecure=true: got unexpected err=Get https://127.0.0.1:33781: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33785: remote error: internal error
--- FAIL: TestClientWithCorrectTLSServerName (0.00s)
    client_test.go:685: expected successful TLS connection, got error: Get https://127.0.0.1:33784: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestClientWithIncorrectTLSServerName (0.00s)
    client_test.go:704: wanted error mentioning 127.0.0.1 and badserver; got error: Get https://127.0.0.1:33786: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33789: remote error: internal error
--- FAIL: TestTransportUsesTLSConfigServerName (0.00s)
    client_test.go:741: Get https://some-other-host.tld/: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33791: remote error: internal error
--- FAIL: TestResponseSetsTLSConnectionState (0.00s)
    client_test.go:762: Get https://example.com/: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestHTTPSClientDetectsHTTPServer (0.00s)
    client_test.go:783: error = "Get https://127.0.0.1:33792: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found."; want error indicating HTTP response to HTTPS request
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33797: remote error: internal error
--- FAIL: TestClientHeadContentLength_h2 (0.02s)
    client_test.go:816: Head https://127.0.0.1:33796/?cl=1234: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33803: remote error: internal error
--- FAIL: TestClientRedirectEatsBody_h2 (0.00s)
    client_test.go:1072: Get https://127.0.0.1:33802: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33807: remote error: internal error
--- FAIL: TestNewClientServerTest (0.00s)
    clientserver_test.go:101: Head https://127.0.0.1:33806: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
--- FAIL: TestChunkedResponseHeaders_h2 (0.00s)
    clientserver_test.go:127: Get error: Get https://127.0.0.1:33810: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33815: remote error: internal error
--- FAIL: TestH12_HeadContentLengthNoBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Head https://127.0.0.1:33813: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33819: remote error: internal error
--- FAIL: TestH12_HeadContentLengthSmallBody (0.02s)
    clientserver_test.go:176: HTTP/2 request: Head https://127.0.0.1:33817: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33823: remote error: internal error
--- FAIL: TestH12_HeadContentLengthLargeBody (0.05s)
    clientserver_test.go:176: HTTP/2 request: Head https://127.0.0.1:33821: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33827: remote error: internal error
--- FAIL: TestH12_200NoBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33825: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33831: remote error: internal error
--- FAIL: TestH2_204NoBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33829: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33835: remote error: internal error
--- FAIL: TestH2_304NoBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33833: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33839: remote error: internal error
--- FAIL: TestH2_404NoBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33837: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33843: remote error: internal error
--- FAIL: TestH12_SmallBody (0.02s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33841: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33847: remote error: internal error
--- FAIL: TestH12_ExplicitContentLength (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33845: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33851: remote error: internal error
--- FAIL: TestH12_FlushBeforeBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33849: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33855: remote error: internal error
--- FAIL: TestH12_FlushMidBody (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33853: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33859: remote error: internal error
--- FAIL: TestH12_Head_ExplicitLen (0.00s)
    clientserver_test.go:176: HTTP/2 request: Head https://127.0.0.1:33857: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33863: remote error: internal error
--- FAIL: TestH12_Head_ImplicitLen (0.02s)
    clientserver_test.go:176: HTTP/2 request: Head https://127.0.0.1:33861: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33867: remote error: internal error
--- FAIL: TestH12_HandlerWritesTooLittle (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33865: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33871: remote error: internal error
--- FAIL: TestH12_HandlerWritesTooMuch (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33869: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33875: remote error: internal error
--- FAIL: TestH12_AutoGzip (0.05s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33873: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33879: remote error: internal error
--- FAIL: TestH12_AutoGzip_Disabled (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33877: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33883: remote error: internal error
--- FAIL: Test304Responses_h2 (0.00s)
    clientserver_test.go:427: Get https://127.0.0.1:33882: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33887: remote error: internal error
--- FAIL: TestH12_ServerEmptyContentLength (0.00s)
    clientserver_test.go:176: HTTP/2 request: Get https://127.0.0.1:33885: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33891: remote error: internal error
--- FAIL: TestH12_RequestContentLength_Known_NonZero (0.02s)
    clientserver_test.go:176: HTTP/2 request: Post https://127.0.0.1:33889: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33895: remote error: internal error
--- FAIL: TestH12_RequestContentLength_Known_Zero (0.00s)
    clientserver_test.go:176: HTTP/2 request: Post https://127.0.0.1:33893: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33899: remote error: internal error
--- FAIL: TestH12_RequestContentLength_Unknown (0.00s)
    clientserver_test.go:176: HTTP/2 request: Post https://127.0.0.1:33897: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33903: remote error: internal error
--- FAIL: TestCancelRequestMidBody_h2 (0.00s)
    clientserver_test.go:503: Get https://127.0.0.1:33902: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33907: remote error: internal error
--- FAIL: TestTrailersClientToServer_h2 (0.00s)
    clientserver_test.go:577: Post https://127.0.0.1:33906: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33911: remote error: internal error
--- FAIL: TestTrailersServerToClient_h2 (0.02s)
    clientserver_test.go:614: Get https://127.0.0.1:33910: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33915: remote error: internal error
--- FAIL: TestTrailersServerToClient_Flush_h2 (0.00s)
    clientserver_test.go:614: Get https://127.0.0.1:33914: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33919: remote error: internal error
--- FAIL: TestResponseBodyReadAfterClose_h2 (0.00s)
    clientserver_test.go:673: Get https://127.0.0.1:33918: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33923: remote error: internal error
--- FAIL: TestConcurrentReadWriteReqBody_h2 (0.00s)
    clientserver_test.go:723: Post https://127.0.0.1:33922: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33927: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33928: remote error: internal error
--- FAIL: TestConnectRequest_h2 (0.06s)
    clientserver_test.go:776: 0. RoundTrip = tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:776: 1. RoundTrip = tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33932: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33933: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33934: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33935: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33936: remote error: internal error
--- FAIL: TestTransportUserAgent_h2 (0.00s)
    clientserver_test.go:839: 0. RoundTrip = Get https://127.0.0.1:33931: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:839: 1. RoundTrip = Get https://127.0.0.1:33931: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:839: 2. RoundTrip = Get https://127.0.0.1:33931: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:839: 3. RoundTrip = Get https://127.0.0.1:33931: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:839: 4. RoundTrip = Get https://127.0.0.1:33931: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33940: read tcp 127.0.0.1:33939->127.0.0.1:33940: use of closed network connection
--- FAIL: TestStarRequestFoo_h2 (0.00s)
    clientserver_test.go:882: RoundTrip = tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33944: remote error: internal error
--- FAIL: TestStarRequestOptions_h2 (0.00s)
    clientserver_test.go:882: RoundTrip = tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33946: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33949: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33947: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33948: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33950: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33951: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33952: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33953: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33954: remote error: internal error
2016/05/11 15:48:27 http: TLS handshake error from 127.0.0.1:33955: remote error: internal error
--- FAIL: TestTransportDiscardsUnneededConns (2.52s)
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:963: Get: Get https://127.0.0.1:33945: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    clientserver_test.go:1000: 10 connections opened, 10 closed; want 9 to close
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:33965: remote error: internal error
--- FAIL: TestTransportGCRequest_Body_h2 (0.00s)
    clientserver_test.go:1025: Post https://127.0.0.1:33964: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:33969: remote error: internal error
--- FAIL: TestTransportGCRequest_NoBody_h2 (0.00s)
    clientserver_test.go:1025: Post https://127.0.0.1:33968: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: panic serving 127.0.0.1:33971: CryptAcquireContext: The specified procedure could not be found.
goroutine 672 [running]:
net/http.(*conn).serve.func1(0xc08253c400)
    C:/Go/src/net/http/server.go:1389 +0xc8
panic(0x8d5a60, 0xc082613140)
    C:/Go/src/runtime/panic.go:443 +0x4f7
mime/multipart.randomBoundary(0x0, 0x0)
    C:/Go/src/mime/multipart/writer.go:76 +0xef
mime/multipart.NewWriter(0xf9eae8, 0xc082113ed8, 0xc281a8)
    C:/Go/src/mime/multipart/writer.go:29 +0x23
net/http.rangesMIMESize(0xc082613100, 0x2, 0x2, 0x9f0e60, 0x19, 0xb, 0x0)
    C:/Go/src/net/http/fs.go:606 +0x86
net/http.serveContent(0x2ed09f0, 0xc082588f70, 0xc082146700, 0xc082113ec9, 0x4, 0xecea91da0, 0x0, 0xc0b960, 0xc0826130a0, 0xf88d78, ...)
    C:/Go/src/net/http/fs.go:224 +0xa55
net/http.serveFile(0x2ed09f0, 0xc082588f70, 0xc082146700, 0xf88bd0, 0xc082113e70, 0x9951c9, 0x4, 0x2ed0800)
    C:/Go/src/net/http/fs.go:422 +0x932
net/http.ServeFile(0x2ed09f0, 0xc082588f70, 0xc082146700, 0x9951c0, 0xd)
    C:/Go/src/net/http/fs.go:475 +0x17a
net/http_test.TestServeFile.func1(0x2ed09f0, 0xc082588f70, 0xc082146700)
    C:/Go/src/net/http/fs_test.go:76 +0x51
net/http.HandlerFunc.ServeHTTP(0xa6bac0, 0x2ed09f0, 0xc082588f70, 0xc082146700)
    C:/Go/src/net/http/server.go:1618 +0x41
net/http.serverHandler.ServeHTTP(0xc08253c300, 0x2ed09f0, 0xc082588f70, 0xc082146700)
    C:/Go/src/net/http/server.go:2081 +0x1a5
net/http.(*conn).serve(0xc08253c400)
    C:/Go/src/net/http/server.go:1472 +0xf35
created by net/http.(*Server).Serve
    C:/Go/src/net/http/server.go:2137 +0x455
2016/05/11 15:48:30 http: panic serving 127.0.0.1:33972: CryptAcquireContext: The specified procedure could not be found.
goroutine 852 [running]:
net/http.(*conn).serve.func1(0xc08253c800)
    C:/Go/src/net/http/server.go:1389 +0xc8
panic(0x8d5a60, 0xc082613460)
    C:/Go/src/runtime/panic.go:443 +0x4f7
mime/multipart.randomBoundary(0x0, 0x0)
    C:/Go/src/mime/multipart/writer.go:76 +0xef
mime/multipart.NewWriter(0xf9eae8, 0xc08220c158, 0xc08220c0eb)
    C:/Go/src/mime/multipart/writer.go:29 +0x23
net/http.rangesMIMESize(0xc0826133c0, 0x2, 0x2, 0x9f0e60, 0x19, 0xb, 0x0)
    C:/Go/src/net/http/fs.go:606 +0x86
net/http.serveContent(0x2ed09f0, 0xc082589380, 0xc082146000, 0xc08220c149, 0x4, 0xecea91da0, 0x0, 0xc0b960, 0xc082613360, 0xf88d78, ...)
    C:/Go/src/net/http/fs.go:224 +0xa55
net/http.serveFile(0x2ed09f0, 0xc082589380, 0xc082146000, 0xf88bd0, 0xc08220c0f0, 0x9951c9, 0x4, 0x2ed0800)
    C:/Go/src/net/http/fs.go:422 +0x932
net/http.ServeFile(0x2ed09f0, 0xc082589380, 0xc082146000, 0x9951c0, 0xd)
    C:/Go/src/net/http/fs.go:475 +0x17a
net/http_test.TestServeFile.func1(0x2ed09f0, 0xc082589380, 0xc082146000)
    C:/Go/src/net/http/fs_test.go:76 +0x51
net/http.HandlerFunc.ServeHTTP(0xa6bac0, 0x2ed09f0, 0xc082589380, 0xc082146000)
    C:/Go/src/net/http/server.go:1618 +0x41
net/http.serverHandler.ServeHTTP(0xc08253c300, 0x2ed09f0, 0xc082589380, 0xc082146000)
    C:/Go/src/net/http/server.go:2081 +0x1a5
net/http.(*conn).serve(0xc08253c800)
    C:/Go/src/net/http/server.go:1472 +0xf35
created by net/http.(*Server).Serve
    C:/Go/src/net/http/server.go:2137 +0x455
--- FAIL: TestServeFile (0.00s)
    fs_test.go:1007: range test "bytes=0-0,-2": for URL "http://127.0.0.1:33970", send error: Get http://127.0.0.1:33970: EOF
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:33994: remote error: internal error
--- FAIL: TestServeFileWithContentEncoding_h2 (0.00s)
    fs_test.go:533: Get https://127.0.0.1:33993: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:34008: remote error: internal error
--- FAIL: TestNextProtoUpgrade (0.00s)
    npn_test.go:51: Get https://127.0.0.1:34007: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:34012: remote error: internal error
--- FAIL: TestRedirect_h2 (0.00s)
    request_test.go:199: Get https://127.0.0.1:34011: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:34033: remote error: internal error
--- FAIL: TestSetsRemoteAddr_h2 (0.00s)
    serve_test.go:756: Get error: Get https://127.0.0.1:34032: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
2016/05/11 15:48:30 http: TLS handshake error from 127.0.0.1:34042: remote error: internal error
--- FAIL: TestHeadResponses_h2 (0.02s)
    serve_test.go:919: Head https://127.0.0.1:34041: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
panic: runtime error: invalid memory address or nil pointer dereference [recovered]
    panic: runtime error: invalid memory address or nil pointer dereference
[signal 0xc0000005 code=0x0 addr=0x60 pc=0x57a72a]

goroutine 1102 [running]:
panic(0x8f49a0, 0xc082006110)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.tRunner.func1(0xc08223ca20)
    C:/Go/src/testing/testing.go:467 +0x199
panic(0x8f49a0, 0xc082006110)
    C:/Go/src/runtime/panic.go:443 +0x4f7
net/http_test.testHeadResponses(0xc08223ca20, 0xc013a87801)
    C:/Go/src/net/http/serve_test.go:921 +0x28a
net/http_test.TestHeadResponses_h2(0xc08223ca20)
    C:/Go/src/net/http/serve_test.go:900 +0x2d
testing.tRunner(0xc08223ca20, 0xc090f0)
    C:/Go/src/testing/testing.go:473 +0x9f
created by testing.RunTests
    C:/Go/src/testing/testing.go:582 +0x899
FAIL    net/http    4.609s
ok      net/http/cgi    1.735s
ok      net/http/cookiejar  1.158s
ok      net/http/fcgi   0.734s
ok      net/http/httptest   1.812s
ok      net/http/httputil   0.860s
ok      net/http/internal   0.484s
ok      net/internal/socktest   0.360s
ok      net/mail    0.484s
ok      net/rpc 1.344s
ok      net/rpc/jsonrpc 0.764s
--- FAIL: TestTLSClient (0.00s)
    smtp_test.go:567: failed to handle connection: remote error: internal error
--- FAIL: TestTLSConnState (0.00s)
    smtp_test.go:602: StartTLS: tls: short read from Rand: CryptAcquireContext: The specified procedure could not be found.
    smtp_test.go:588: server error: remote error: internal error
FAIL
FAIL    net/smtp    0.752s
ok      net/textproto   0.529s
ok      net/url 0.844s
ok      os  1.391s
ok      os/exec 19.909s
ok      os/signal   3.781s
--- FAIL: TestCurrent (0.00s)
panic: Failed to load userenv.dll: The specified module could not be found. [recovered]
    panic: Failed to load userenv.dll: The specified module could not be found.

goroutine 6 [running]:
panic(0x5668e0, 0xc082064270)
    C:/Go/src/runtime/panic.go:481 +0x3f4
testing.tRunner.func1(0xc08207a000)
    C:/Go/src/testing/testing.go:467 +0x199
panic(0x5668e0, 0xc082064270)
    C:/Go/src/runtime/panic.go:443 +0x4f7
syscall.(*LazyProc).mustFind(0xc082005c80)
    C:/Go/src/syscall/dll_windows.go:280 +0x6a
syscall.(*LazyProc).Addr(0xc082005c80, 0x43dd5c)
    C:/Go/src/syscall/dll_windows.go:287 +0x28
syscall.GetUserProfileDirectory(0x18c, 0xc082040d00, 0xc082033dcc, 0x0, 0x0)
    C:/Go/src/syscall/zsyscall_windows.go:1865 +0x3f
syscall.Token.GetUserProfileDirectory(0x18c, 0x0, 0x0, 0x0, 0x0)
    C:/Go/src/syscall/security_windows.go:365 +0xae
os/user.current(0x0, 0x0, 0x0)
    C:/Go/src/os/user/lookup_windows.go:115 +0x1e1
os/user.Current(0xc08207a000, 0x0, 0x0)
    C:/Go/src/os/user/lookup.go:9 +0x2b
os/user.TestCurrent(0xc08207a000)
    C:/Go/src/os/user/user_test.go:21 +0x3f
testing.tRunner(0xc08207a000, 0x670ac0)
    C:/Go/src/testing/testing.go:473 +0x9f
created by testing.RunTests
    C:/Go/src/testing/testing.go:582 +0x899
FAIL    os/user 0.375s
ok      path    0.719s
ok      path/filepath   5.672s
ok      reflect 2.469s
ok      regexp  2.125s
ok      regexp/syntax   1.328s
ok      runtime 101.468s
ok      runtime/debug   0.753s
ok      runtime/internal/atomic 1.141s
ok      runtime/pprof   3.283s
ok      runtime/trace   23.406s
ok      sort    2.453s
ok      strconv 0.875s
ok      strings 2.765s
ok      sync    4.361s
ok      sync/atomic 3.748s
ok      syscall 0.716s
ok      testing 4.282s
ok      testing/quick   0.514s
ok      text/scanner    0.719s
ok      text/tabwriter  0.544s
ok      text/template   1.266s
ok      text/template/parse 0.532s
--- FAIL: TestLocalZoneAbbr (0.09s)
    zoneinfo_windows_test.go:19: Parse failed: parsing time "Wed, 11 May 2016 15:48:51 -0700" as "Mon, 02 Jan 2006 15:04:05 MST": cannot parse "-0700" as "MST"
FAIL
FAIL    time    7.297s
ok      unicode 0.859s
ok      unicode/utf16   0.269s
ok      unicode/utf8    1.047s
ok      cmd/addr2line   4.861s
ok      cmd/asm/internal/asm    1.578s
ok      cmd/asm/internal/lex    0.359s
ok      cmd/compile/internal/big    1.406s
ok      cmd/compile/internal/gc 2.016s
ok      cmd/cover   6.016s
ok      cmd/doc 0.548s
ok      cmd/fix 0.566s
ok      cmd/go  148.876s
ok      cmd/gofmt   0.500s
ok      cmd/internal/goobj  0.359s
ok      cmd/internal/obj    0.361s
ok      cmd/internal/obj/x86    0.438s
ok      cmd/internal/unvendor/golang.org/x/arch/arm/armasm  0.391s
ok      cmd/internal/unvendor/golang.org/x/arch/x86/x86asm  2.297s
ok      cmd/nm  5.312s
ok      cmd/objdump 6.641s
ok      cmd/pack    8.844s
ok      cmd/pprof/internal/profile  1.456s
ok      cmd/vet 0.734s

Workaround

This is a giant hack, but a possible workaround for this problem is to eagerly load the problematic DLLs instead of letting the delay-load machinery attempt to do so. What I did locally to unblock me was adding LoadLibrary calls to loadOptionalSyscalls in os1_windows.go:

@@ -116,6 +116,11 @@
 func loadOptionalSyscalls() {
    var (
        kernel32dll                 = []byte("kernel32.dll\000")
+       cryptspdll                  = []byte("cryptsp.dll\000")
+       iphlpapidll                 = []byte("iphlpapi.dll\000")
+       netapi32dll                 = []byte("netapi32.dll\000")
+       userenvdll                  = []byte("userenv.dll\000")
+       secur32dll                  = []byte("secur32.dll\000")
        addVectoredContinueHandler  = []byte("AddVectoredContinueHandler\000")
        getQueuedCompletionStatusEx = []byte("GetQueuedCompletionStatusEx\000")
        addDllDirectory             = []byte("AddDllDirectory\000")
@@ -130,6 +135,12 @@
    _AddVectoredContinueHandler = windowsFindfunc(addVectoredContinueHandler, k32)
    _GetQueuedCompletionStatusEx = windowsFindfunc(getQueuedCompletionStatusEx, k32)
    _LoadLibraryExW = windowsFindfunc(loadLibraryExW, k32)
+
+   stdcall1(_LoadLibraryA, uintptr(unsafe.Pointer(&cryptspdll[0])))
+   stdcall1(_LoadLibraryA, uintptr(unsafe.Pointer(&iphlpapidll[0])))
+   stdcall1(_LoadLibraryA, uintptr(unsafe.Pointer(&userenvdll[0])))
+   stdcall1(_LoadLibraryA, uintptr(unsafe.Pointer(&netapi32dll[0])))
+   stdcall1(_LoadLibraryA, uintptr(unsafe.Pointer(&secur32dll[0])))
 }

[bradfitz]

/cc @alexbrainman @jstarks for Windows advice.

[mattn]

Did you try to specify DONT_RESOLVE_DLL_REFERENCES (that is flag for LoadLibraryEx) for loading cryptsp.dll ?

[jblazquez]

@mattn, do you mean whether I tried passing that flag for my hacky workaround patch to os1_windows.go? If so, no, I didn't, but it works fine with plain LoadLibrary as I mentioned.

Note that the original problem manifests itself during an implicit delay load of cryptsp.dll, not due to anyone calling LoadLibrary or LoadLibraryEx.

[jstarks]

@jblazquez Which server edition is this? I'm not able to repro this on more recent (internal) builds of Server 2016... But maybe this only affects certain editions.

[jblazquez]

@jstarks This was on a Datacenter Edition with Desktop Experience, but I just reinstalled the same OS from scratch on another VM and I cannot repro it there, so maybe something is corrupted on my original install.

I'll dig into it a bit more and report back if I can track down what caused it originally. Feel free to close this issue as no repro; I can reopen it if I get more information.

[mattn]

@jblazquez Ah, no. I mean that to add code to load cryptsp.dll on your code.

FYI, I tried this on Windows Server Datacenter Edition 2012R2. But not reproduced.

[jblazquez]

I'm unable to reproduce this problem, so I'll chalk it up to a corrupt install of some sort.