[THRIFT-3156] Node TLS: server executes processing logic two full times

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 0.10.0
• Component/s: Node.js - Library

Environment

OS X w/ Node.js

• Assignee: Unassigned
• Reporter: John Batte
• Created: 15/May/15 19:39
• Updated: 12/Aug/16 03:29
• Resolved: 11/Apr/16 23:44

Description

Using attached thrift-jira-evidence.zip

$ unzip thrift-jira-evidence.zip
$ cd thrift-jira-evidence

Note: you'll need a total of three certs: ca.crt, server.crt, and server.key. These have not been provided in the evidence.

Server side reproduce steps

1. cd server
2. Copy ca.crt to config/ssl/ca.crt
3. Copy server.crt to config/ssl/server.crt
4. Copy server.key to config/ssl/server.key
5. npm install
6. NODE_DEBUG="tls" npm start

Server output after server start

> thrift-tls-experiment@0.0.0 start /your/path/to/server
> node ./src/node/index.js

Thrift service now listening on port 9797

Client side reproduce steps

1. cd client
2. Copy ca.crt to config/ssl/ca.crt
3. npm install
4. NODE_DEBUG="tls" npm start

Client output after client start

> thrift-tls-experiment@0.0.0 start /your/path/to/client
> node ./src/node/index.js

Creating connection host: localhost port: 9797
Creating client
Sending: Hello, World!
TLS 15599: secure established
Response received!
Killing connection
Success! Hello, World! >> !dlroW ,olleH

Server output after client start

TLS 15547: onhandshakestart
TLS 15547: onhandshakedone
TLS 15547: secure established
Mapping to specific processor call
Trace: Inside process_reverse
    at TermReverserProcessor.process_reverse (/your/path/to/server/src/node/contracts/TermReverser.js:196:11)
    at TermReverserProcessor.process (/your/path/to/server/src/node/contracts/TermReverser.js:183:39)
    at /your/path/to/server/node_modules/thrift/lib/thrift/server.js:55:21
    at TLSSocket.<anonymous> (/your/path/to/server/node_modules/thrift/lib/thrift/transport.js:63:7)
    at TLSSocket.emit (events.js:107:17)
    at readableAddChunk (_stream_readable.js:163:16)
    at TLSSocket.Readable.push (_stream_readable.js:126:10)
    at TCP.onread (net.js:529:20)
Reversing: Hello, World! call count 1
Mapping to specific processor call
Mapping to specific processor call
Trace: Inside process_reverse
    at TermReverserProcessor.process_reverse (/your/path/to/server/src/node/contracts/TermReverser.js:196:11)
    at TermReverserProcessor.process (/your/path/to/server/src/node/contracts/TermReverser.js:183:39)
    at /your/path/to/server/node_modules/thrift/lib/thrift/server.js:55:21
    at TLSSocket.<anonymous> (/your/path/to/server/node_modules/thrift/lib/thrift/transport.js:63:7)
    at TLSSocket.emit (events.js:107:17)
    at readableAddChunk (_stream_readable.js:163:16)
    at TLSSocket.Readable.push (_stream_readable.js:126:10)
    at TCP.onread (net.js:529:20)
Reversing: Hello, World! call count 2
Mapping to specific processor call

Conclusion: something is resetting the stream position to zero after server-side processing is complete, causing a second complete execution to occur, even though the client only receives one response. This issue does not occur with the equivalent code when TLS has been "turned off". My colleagues and I are having difficulty locating the errant code. Any help is appreciated.

Issue Links

• relates to: THRIFT-3786 Node.js TLS emits 'connect' before connection is ready