Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

New Node.js package does not support deferred responses (timeouts or Promises). #175

Closed
phyllisstein opened this issue Oct 18, 2018 · 12 comments
Assignees

Comments

@phyllisstein
Copy link

👋 Hey folks! In an access of enthusiasm for the recently-landed support for Node.js applications, I've been playing around with integrating some simple apps using unit-http. So far, I've had great success getting Unit to work with barebones Express apps---for example, this code...

#!/usr/bin/env node

const {
  createServer,
  IncomingMessage,
  ServerResponse,
} = require('unit-http')

require('http').ServerResponse = ServerResponse
require('http').IncomingMessage = IncomingMessage

const express = require('express')

const app = express()

app.get('/', (req, res) => {
  res.set('X-Unit-Type', 'Absolute')
  res.send('Hello, Unit!')
})

createServer(app).listen()

...combined with this configuration...

{
  "listeners": {
    "*:8080": {
      "application": "hello-unit"
    }
  },
  "applications": {
    "hello-unit": {
      "type": "external",
      "working_directory": "/Users/daniel/Repos/Personal/hello-unit",
      "executable": "app.js"
    }
  }
}

...works just beautifully, which is quite exciting.

The difficulty I've noticed is that any asynchronicity in the request handler causes Unit to choke---it blocks forever on the request, and logs something like the following:

2018/10/18 01:59:07.614 [debug] 7209#4384863 [unit] #3: GET / (0)
2018/10/18 01:59:07.614 [debug] 7208#4384951 work queue: fast
2018/10/18 01:59:07.614 [debug] 7208#4384951 *19 buf ts completion: 7FD194016200 7FD194016278
2018/10/18 01:59:07.614 [debug] 7208#4384951 mp 7FD1948000C0 release: 2
2018/10/18 01:59:07.614 [debug] 7208#4384951 work queue: fast
2018/10/18 01:59:07.614 [debug] 7208#4384951 kevent(17) changes:0 timeout:-1
Thu, 18 Oct 2018 05:59:07 GMT express:router dispatching GET /
Thu, 18 Oct 2018 05:59:07 GMT express:router query  : /
Thu, 18 Oct 2018 05:59:07 GMT express:router expressInit  : /

After the request has been manually aborted by the client, it logs this:

2018/10/18 01:59:17.360 [debug] 7208#4384951 kevent(17): 1
2018/10/18 01:59:17.360 [debug] 7208#4384951 kevent: id:36 ft:-1 fl:8025 ff:0 d:0 ud:7FD194A00900
2018/10/18 01:59:17.360 [debug] 7208#4384951 *19 blocked read event fd:36
2018/10/18 01:59:17.360 [debug] 7208#4384951 timer expire minimum: 180558476:94168224
2018/10/18 01:59:17.360 [debug] 7208#4384951 kevent(17) changes:0 timeout:-1

This is a problem for Express, which at least supports asynchronicity in its middlewares; but it's the kiss of death for Koa, which is built entirely on Promises that, when run through Unit, never seem to resolve. (I can produce a Koa case as well if that's helpful.)

I'm trying to do some debugging to figure out what might be going on, but in all honesty I don't know N-API (or, for that matter, C/C++) very well so it's a little tough.

Here's a simpler snippet of code that fails in this style:

#!/usr/bin/env node

const { Server } = require('unit-http')

const srv = new Server((req, res) => {
  return Promise.resolve().then(() => {
    console.log()
    console.log('Thenable resolved!')
    console.log(req)
    console.log(res)
    console.log()

    res.write('Hello, Unit!')
  })
})

srv.on('request', (req, res) => {
  console.log()
  console.log('Request event fired!')
  console.log(req)
  console.log(res)
  console.log()
})

srv.listen()

Running this through Unit, I get the following output from the daemon:

Daemon Output
Request event fired!
ServerRequest {
  _events: {},
  _eventsCount: 0,
  _maxListeners: undefined,
  server:
   Server {
     _events: { request: [Array] },
     _eventsCount: 1,
     _maxListeners: undefined,
     unit: Unit { server: [Circular] },
     socket: { [Function: Socket] super_: [Function] },
     request: { [Function: ServerRequest] super_: [Function] },
     response: { [Function: ServerResponse] super_: [Function] } },
  socket:
   Socket {
     _events: {},
     _eventsCount: 0,
     _maxListeners: undefined,
     readable: true,
     writable: true },
  headers:
   { Host: 'localhost:8080',
     'User-Agent': 'HTTPie/0.9.9',
     'Accept-Encoding': 'gzip, deflate',
     Accept: '*/*',
     Connection: 'keep-alive' },
  raw_headers:
   [ 'Host',
     'localhost:8080',
     'User-Agent',
     'HTTPie/0.9.9',
     'Accept-Encoding',
     'gzip, deflate',
     'Accept',
     '*/*',
     'Connection',
     'keep-alive' ],
  httpVersion: 'HTTP/1.1',
  method: 'GET',
  url: '/' }
ServerResponse {
  _events: {},
  _eventsCount: 0,
  _maxListeners: undefined,
  headers: {},
  socket:
   Socket {
     _events: {},
     _eventsCount: 0,
     _maxListeners: undefined,
     readable: true,
     writable: true },
  _req_point: 4355788040 }

...and the following tail of debug logs:

unit.log
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 http conn init
2018/10/18 02:05:59.266 [debug] 17802#4450543 work queue: read
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 kqueue conn read fd:36
2018/10/18 02:05:59.266 [debug] 17802#4450538 kevent(14): 1
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 conn read fd:36 rdy:0 cl:0
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 kevent(19) set event: id:36 ft:-1 fl:0025
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 timer add: 0:0 180000:94750129
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 timer change: 94750129:0
2018/10/18 02:05:59.266 [debug] 17802#4450543 timers changes: 1
2018/10/18 02:05:59.266 [debug] 17802#4450537 kevent(13): 1
2018/10/18 02:05:59.266 [debug] 17802#4450537 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE502530
2018/10/18 02:05:59.266 [debug] 17802#4450537 timer expire minimum: 180963493:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450537 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450537 kevent fd:10 avail:1
2018/10/18 02:05:59.266 [debug] 17802#4450538 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE405180
2018/10/18 02:05:59.266 [debug] 17802#4450539 kevent(15): 1
2018/10/18 02:05:59.266 [debug] 17802#4450538 timer expire minimum: 180963493:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450541 kevent(17): 1
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 timer rbtree insert: 94750129
2018/10/18 02:05:59.266 [debug] 17802#4450543 *16 timer found minimum: 94750129:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450543 kevent(19) changes:1 timeout:180000
2018/10/18 02:05:59.266 [debug] 17802#4450541 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE405080
2018/10/18 02:05:59.266 [debug] 17802#4450537 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450538 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450538 kevent fd:10 avail:1
2018/10/18 02:05:59.266 [debug] 17802#4450537 kevent(13) changes:0 timeout:-1
2018/10/18 02:05:59.266 [debug] 17802#4450539 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE602CB0
2018/10/18 02:05:59.266 [debug] 17802#4450538 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450539 timer expire minimum: 180963493:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450538 kevent(14) changes:0 timeout:-1
2018/10/18 02:05:59.266 [debug] 17802#4450539 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450539 kevent fd:10 avail:1
2018/10/18 02:05:59.268 [debug] 17802#4450543 kevent(19): 1
2018/10/18 02:05:59.268 [debug] 17802#4450543 kevent: id:36 ft:-1 fl:0025 ff:0 d:135 ud:7FC4BE602580
2018/10/18 02:05:59.268 [debug] 17802#4450543 timer expire minimum: 94750129:94570131
2018/10/18 02:05:59.268 [debug] 17802#4450543 work queue: read
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 kqueue conn read fd:36
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 conn read fd:36 rdy:1 cl:0
2018/10/18 02:05:59.266 [debug] 17802#4450541 timer expire minimum: 180963493:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450542 kevent(18): 1
2018/10/18 02:05:59.266 [debug] 17802#4450536 kevent(12): 1
2018/10/18 02:05:59.266 [debug] 17802#4450542 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE6029D0
2018/10/18 02:05:59.266 [debug] 17802#4450540 kevent(16): 1
2018/10/18 02:05:59.266 [debug] 17802#4450542 timer expire minimum: 180963493:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450540 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BE404AF0
2018/10/18 02:05:59.266 [debug] 17802#4450542 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450541 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450540 timer expire minimum: 180963490:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450536 kevent: id:10 ft:-1 fl:0005 ff:0 d:1 ud:7FC4BF900650
2018/10/18 02:05:59.266 [debug] 17802#4450541 kevent fd:10 avail:1
2018/10/18 02:05:59.266 [debug] 17802#4450542 kevent fd:10 avail:1
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(16, 2160): 7FC4BF073A00
2018/10/18 02:05:59.266 [debug] 17802#4450536 timer expire minimum: 180963490:94570129
2018/10/18 02:05:59.266 [debug] 17802#4450539 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450541 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450540 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450539 kevent(15) changes:0 timeout:-1
2018/10/18 02:05:59.266 [debug] 17802#4450542 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450542 kevent(18) changes:0 timeout:-1
2018/10/18 02:05:59.268 [debug] 17802#4450543 recvbuf: 0, 7FC4BF073A48, 2048
2018/10/18 02:05:59.266 [debug] 17802#4450541 kevent(17) changes:0 timeout:-1
2018/10/18 02:05:59.266 [debug] 17802#4450540 kevent fd:10 avail:1
2018/10/18 02:05:59.266 [debug] 17802#4450540 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.266 [debug] 17802#4450540 kevent(16) changes:0 timeout:-1
2018/10/18 02:05:59.266 [debug] 17802#4450536 work queue: accept
2018/10/18 02:05:59.266 [debug] 17802#4450536 kevent fd:10 avail:1
2018/10/18 02:05:59.266 [debug] 17802#4450536 accept(10) (35: Resource temporarily unavailable)
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 recv(36, 7FC4BF073A48, 2048, 0x0): 135
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 kevent fd:36 avail:0 eof:0
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 timer disable: 94750129:2
2018/10/18 02:05:59.268 [debug] 17802#4450543 work queue: fast
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 h1p conn proto init
2018/10/18 02:05:59.266 [debug] 17802#4450536 kevent(12) changes:0 timeout:-1
2018/10/18 02:05:59.268 [debug] 17802#4450543 malloc(136): 7FC4BF8002E0
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(128, 1024): 7FC4BF069200
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 h1p conn request init
2018/10/18 02:05:59.268 [debug] 17802#4450543 malloc(168): 7FC4BE603490
2018/10/18 02:05:59.268 [debug] 17802#4450543 malloc(136): 7FC4BE603540
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(128, 1024): 7FC4BF074400
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 h1p conn header parse
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 timer disable: 94750129:0
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 h1p request body read -1 te:0
2018/10/18 02:05:59.268 [debug] 17802#4450543 work queue: fast
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(16, 720): 7FC4BE6035D0
2018/10/18 02:05:59.268 [debug] 17802#4450543 mp 7FC4BE603490 retain: 2
2018/10/18 02:05:59.268 [debug] 17802#4450543 malloc(136): 7FC4BE6038A0
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(128, 1024): 7FC4BF074800
2018/10/18 02:05:59.268 [debug] 17802#4450543 posix_memalign(128, 128): 7FC4BE603980
2018/10/18 02:05:59.268 [debug] 17802#4450543 *16 rpc: stream #3 registered
2018/10/18 02:05:59.268 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE5009C0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE5009C0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 already have port for app 'hello-unit' 7FC4BE5009C0
2018/10/18 02:05:59.269 [debug] 17802#4450543 posix_memalign(128, 128): 7FC4BE603A80
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 rpc: stream #3 assigned uniq pid 17803 (7FC4C1001508)
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE601910) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 process port (17802, 3) not found
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE601910) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 mp 7FC4BE501290 retain: 2
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 send port 25 to process 17803
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE601AE0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 using plain mode
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 sendbuf: 0, 7FC4BF065A78, 32
2018/10/18 02:05:59.269 [debug] 17802#4450543 sendmsg(11, 25, 2): 48
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE601AE0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE601910) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 posix_memalign(128, 128): 7FC4BE603B80
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE601910) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 request 302 bytes shm buffer
2018/10/18 02:05:59.269 [debug] 17802#4450543 mp 7FC4BE501290 retain: 3
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE6018C0) enter
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] port_recv(9): 48
2018/10/18 02:05:59.269 [debug] 17802#4450543 malloc(16): 7FC4BE600CF0
2018/10/18 02:05:59.269 [debug] 17802#4450543 realloc(0, 8): 7FC4BFA00380
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] #0: new_port: 17802,3 fd 28
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 shm_open(/unit.17802.bc060115): 37
2018/10/18 02:05:59.269 [debug] 17802#4450543 mmap(0, 10489856, 3, 1, 37, 0): 101749000
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 send mmap fd 37 to process 17803
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] add_port: 17802,3 in_fd -1 out_fd 28
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE601AE0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 sendmsg(11, 37, 1): 16
2018/10/18 02:05:59.269 [debug] 17802#4450543 close(37)
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] port_recv(9): 16
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE601AE0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 new mmap #0 created for 17802 -> 17803
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE6018C0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 outgoing mmap buf allocation: 7FC4BF065280 [10174A000,16384] 17802->17803,0,0
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 fields_count=5
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 add field 0xE6EB, 0, 4, 7FC4BF073A58 : 14 7FC4BF073A5E
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 add field 0x0220, 0, 10, 7FC4BF073A6E : 12 7FC4BF073A7A
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 add field 0x9683, 0, 15, 7FC4BF073A88 : 13 7FC4BF073A99
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] incoming_mmap: fd 29 from process 17802
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 add field 0xD871, 0, 6, 7FC4BF073AA8 : 3 7FC4BF073AB0
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 add field 0x25AB, 0, 10, 7FC4BF073AB5 : 10 7FC4BF073AC1
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 about to send 302 bytes buffer to app process port 11
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 request tracking for stream #3
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE6018C0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE6018C0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 outgoing tracking allocation: 17802->17803,0,0
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE601AE0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 using mmap mode
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 sendbuf: 0, 10174A000, 302
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 prepare 302 bytes message for transfer to process 17803 via shared memory
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 mmap_msg={0, 0, 302} to 17803
2018/10/18 02:05:59.269 [debug] 17802#4450543 sendmsg(11, -1, 2): 36
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE601AE0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_lock(7FC4BE5009C0) enter
2018/10/18 02:05:59.269 [debug] 17802#4450543 pthread_mutex_unlock(7FC4BE5009C0) exit
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 app 'hello-unit' 7FC4BE5009C0 requests queue is empty, keep the port
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 ra stream #3 update peer
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 ra stream #3 release
2018/10/18 02:05:59.269 [debug] 17802#4450543 work queue: fast
2018/10/18 02:05:59.269 [debug] 17802#4450543 *16 buf ts completion: 7FC4BF065A00 7FC4BF065A78
2018/10/18 02:05:59.269 [debug] 17802#4450543 mp 7FC4BE501290 release: 2
2018/10/18 02:05:59.269 [debug] 17802#4450543 work queue: fast
2018/10/18 02:05:59.269 [debug] 17802#4450543 kevent(19) changes:0 timeout:-1
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] port_recv(9): 36
2018/10/18 02:05:59.269 [debug] 17803#4450517 [unit] #3: mmap_read: [0x108801000,302] 17802->17803,(0,0,302)

2018/10/18 02:05:59.270 [debug] 17803#4450517 [unit] #3: GET / (0)
2018/10/18 02:06:13.652 [debug] 17802#4450543 kevent(19): 1
2018/10/18 02:06:13.652 [debug] 17802#4450543 kevent: id:36 ft:-1 fl:8025 ff:0 d:0 ud:7FC4BE602580
2018/10/18 02:06:13.652 [debug] 17802#4450543 *16 blocked read event fd:36
2018/10/18 02:06:13.652 [debug] 17802#4450543 timer expire minimum: 180970131:94584515
2018/10/18 02:06:13.652 [debug] 17802#4450543 kevent(19) changes:0 timeout:-1

It seems clear that the listeners are being invoked, but beyond that I haven't figured out where they're blocking yet. Is it possible that the N-API scope is being closed too early? Or might it be something else?

Thanks for taking a look, and thanks for all your work on Unit. Can't wait till Node support starts to mature.

@lexborisov
Copy link
Contributor

Hi @phyllisstein

I understand the problem described by you. I am working on solution.
Thank you for report.

@phyllisstein
Copy link
Author

@lexborisov Awesome! Thanks a lot, and please let me know if I can help with any additional debugging info.

@ghost
Copy link

ghost commented Oct 23, 2018

@phyllisstein Hi, may we use the initial sample in our docs?

#!/usr/bin/env node

const {
  createServer,
  IncomingMessage,
  ServerResponse,
} = require('unit-http')

require('http').ServerResponse = ServerResponse
require('http').IncomingMessage = IncomingMessage

const express = require('express')

const app = express()

app.get('/', (req, res) => {
  res.set('X-Unit-Type', 'Absolute')
  res.send('Hello, Unit!')
})

createServer(app).listen()

@phyllisstein
Copy link
Author

phyllisstein commented Oct 23, 2018

Yes, please do! If it's useful to other end-users, I also wrote a longer guide to setting up the Node integration here: https://medium.com/house-organ/what-an-absolute-unit-a36851e72554.

@lexborisov
Copy link
Contributor

lexborisov commented Oct 31, 2018

Hi @phyllisstein

I fixed a problem. Please, try this patch:

# HG changeset patch
# User Alexander Borisov <alexander.borisov@nginx.com>
# Date 1540990311 -10800
#      Wed Oct 31 15:51:51 2018 +0300
# Node ID 99103649afea05f0e935b8b2fd7f928ea86ba0c8
# Parent  31027fb759051f119efedf672145a91de088ebde
Node.js: added async request execution.

diff -r 31027fb75905 -r 99103649afea src/nodejs/unit-http/http_server.js
--- a/src/nodejs/unit-http/http_server.js	Wed Oct 24 16:21:53 2018 +0300
+++ b/src/nodejs/unit-http/http_server.js	Wed Oct 31 15:51:51 2018 +0300
@@ -232,7 +232,6 @@
 
 ServerResponse.prototype.end = function end(chunk, encoding, callback) {
     this._writeBody(chunk, encoding, callback);
-    unit_lib.unit_response_end(this)
 
     this.finished = true;
 
@@ -290,9 +289,9 @@
     EventEmitter.call(this);
 
     this.unit = new unit_lib.Unit();
-    this.unit.createServer();
+    this.unit.server = this;
 
-    this.unit.server = this;
+    this.unit.createServer();
 
     this.socket = Socket;
     this.request = ServerRequest;
@@ -318,10 +317,31 @@
     this.unit.listen();
 };
 
+Server.prototype.run_events = function (server, req, res) {
+    setImmediate(function () {
+        server.emit("request", req, res);
+
+        Promise.resolve().then(() => {
+            let buf = server.unit._read(req.socket.req_pointer);
+
+            if (buf.length != 0) {
+                req.emit("data", buf);
+            }
+
+            req.emit("end");
+        });
+
+        Promise.resolve().then(() => {
+            if (res.finished) {
+                unit_lib.unit_response_end(res);
+            }
+        });
+    });
+};
+
 function connectionListener(socket) {
 }
 
-
 module.exports = {
     STATUS_CODES: http.STATUS_CODES,
     Server,
diff -r 31027fb75905 -r 99103649afea src/nodejs/unit-http/unit.cpp
--- a/src/nodejs/unit-http/unit.cpp	Wed Oct 24 16:21:53 2018 +0300
+++ b/src/nodejs/unit-http/unit.cpp	Wed Oct 31 15:51:51 2018 +0300
@@ -5,6 +5,11 @@
 
 #include "unit.h"
 
+#include <unistd.h>
+#include <fcntl.h>
+
+#include <uv.h>
+
 
 napi_ref Unit::constructor_;
 
@@ -31,11 +36,12 @@
 
     napi_property_descriptor  properties[] = {
         { "createServer", 0, create_server, 0, 0, 0, napi_default, 0 },
-        { "listen", 0, listen, 0, 0, 0, napi_default, 0 }
+        { "listen", 0, listen, 0, 0, 0, napi_default, 0 },
+        { "_read", 0, _read, 0, 0, 0, napi_default, 0 }
     };
 
     status = napi_define_class(env, "Unit", NAPI_AUTO_LENGTH, create, nullptr,
-                               2, properties, &cons);
+                               3, properties, &cons);
     if (status != napi_ok) {
         goto failed;
     }
@@ -158,14 +164,13 @@
 {
     Unit             *obj;
     size_t           argc;
-    napi_value       jsthis;
+    napi_value       jsthis, argv;
     napi_status      status;
-    napi_value       argv[1];
     nxt_unit_init_t  unit_init;
 
     argc = 1;
 
-    status = napi_get_cb_info(env, info, &argc, argv, &jsthis, nullptr);
+    status = napi_get_cb_info(env, info, &argc, &argv, &jsthis, nullptr);
     if (status != napi_ok) {
         goto failed;
     }
@@ -179,6 +184,8 @@
 
     unit_init.data = obj;
     unit_init.callbacks.request_handler = request_handler;
+    unit_init.callbacks.add_port        = add_port;
+    unit_init.callbacks.remove_port     = remove_port;
 
     obj->unit_ctx_ = nxt_unit_init(&unit_init);
     if (obj->unit_ctx_ == NULL) {
@@ -198,41 +205,53 @@
 napi_value
 Unit::listen(napi_env env, napi_callback_info info)
 {
-    int          ret;
-    Unit         *obj;
-    napi_value   jsthis;
-    napi_status  status;
+    return nullptr;
+}
+
 
-    status = napi_get_cb_info(env, info, nullptr, nullptr, &jsthis, nullptr);
+napi_value
+Unit::_read(napi_env env, napi_callback_info info)
+{
+    Unit                     *obj;
+    void                     *data;
+    size_t                   argc;
+    int64_t                  req_pointer;
+    napi_value               jsthis, buffer, argv;
+    napi_status              status;
+    nxt_unit_request_info_t  *req;
+
+    argc = 1;
+
+    status = napi_get_cb_info(env, info, &argc, &argv, &jsthis, nullptr);
     if (status != napi_ok) {
-        goto failed;
+        napi_throw_error(env, NULL, "Failed to get arguments from js");
+        return nullptr;
     }
 
     status = napi_unwrap(env, jsthis, reinterpret_cast<void **>(&obj));
     if (status != napi_ok) {
-        goto failed;
+        napi_throw_error(env, NULL, "Failed to get Unit object form js");
+        return nullptr;
     }
 
-    if (obj->unit_ctx_ == NULL) {
-        napi_throw_error(env, NULL, "Unit context was not created");
+    status = napi_get_value_int64(env, argv, &req_pointer);
+    if (status != napi_ok) {
+        napi_throw_error(env, NULL, "Failed to get request pointer");
         return nullptr;
     }
 
-    ret = nxt_unit_run(obj->unit_ctx_);
-    if (ret != NXT_UNIT_OK) {
-        napi_throw_error(env, NULL, "Failed to run Unit");
+    req = (nxt_unit_request_info_t *) (uintptr_t) req_pointer;
+
+    status = napi_create_buffer(env, (size_t) req->content_length,
+                                &data, &buffer);
+    if (status != napi_ok) {
+        napi_throw_error(env, NULL, "Failed to create request buffer");
         return nullptr;
     }
 
-    nxt_unit_done(obj->unit_ctx_);
-
-    return nullptr;
+    nxt_unit_request_read(req, data, req->content_length);
 
-failed:
-
-    napi_throw_error(env, NULL, "Failed to listen Unit socket");
-
-    return nullptr;
+    return buffer;
 }
 
 
@@ -242,8 +261,9 @@
     Unit         *obj;
     napi_value   socket, request, response;
     napi_value   global, server_obj;
-    napi_value   req_argv[3];
+    napi_value   run_events, events_res;
     napi_status  status;
+    napi_value   events_args[3];
 
     obj = reinterpret_cast<Unit *>(req->unit->data);
 
@@ -284,22 +304,109 @@
         return;
     }
 
-    req_argv[1] = request;
-    req_argv[2] = response;
-
     status = obj->create_headers(req, request);
     if (status != napi_ok) {
         napi_throw_error(obj->env_, NULL, "Failed to create headers");
         return;
     }
 
-    obj->emit(server_obj, "request", sizeof("request") - 1, 3, req_argv);
-    obj->emit_post_data(request, req);
+    status = napi_get_named_property(obj->env_, server_obj, "run_events",
+                                     &run_events);
+    if (status != napi_ok) {
+        napi_throw_error(obj->env_, NULL, "Failed to get"
+                         " 'run_events' function");
+        return;
+    }
+
+    events_args[0] = server_obj;
+    events_args[1] = request;
+    events_args[2] = response;
+
+    status = napi_call_function(obj->env_, server_obj, run_events, 3,
+                                events_args, &events_res);
+    if (status != napi_ok) {
+        napi_throw_error(obj->env_, NULL, "Failed to call"
+                         " 'run_events' function");
+        return;
+    }
 
     napi_close_handle_scope(obj->env_, scope);
 }
 
 
+void
+nxt_uv_read_callback(uv_poll_t *handle, int status, int events)
+{
+    nxt_unit_run_once((nxt_unit_ctx_t *) handle->data);
+}
+
+
+int
+Unit::add_port(nxt_unit_ctx_t *ctx, nxt_unit_port_t *port)
+{
+    int          err;
+    Unit         *obj;
+    uv_loop_t    *loop;
+    uv_poll_t    *uv_handle;
+    napi_status  status;
+
+    if (port->in_fd != -1) {
+        obj = reinterpret_cast<Unit *>(ctx->unit->data);
+
+        if (fcntl(port->in_fd, F_SETFL, O_NONBLOCK) == -1) {
+            napi_throw_error(obj->env_, NULL, "Failed to upgrade read"
+                             " file descriptor to O_NONBLOCK");
+            return -1;
+        }
+
+        status = napi_get_uv_event_loop(obj->env_, &loop);
+        if (status != napi_ok) {
+            napi_throw_error(obj->env_, NULL, "Failed to get uv.loop");
+            return NXT_UNIT_ERROR;
+        }
+
+        uv_handle = new uv_poll_t;
+
+        err = uv_poll_init(loop, uv_handle, port->in_fd);
+        if (err < 0) {
+            napi_throw_error(obj->env_, NULL, "Failed to init uv.poll");
+            return NXT_UNIT_ERROR;
+        }
+
+        err = uv_poll_start(uv_handle, UV_READABLE, nxt_uv_read_callback);
+        if (err < 0) {
+            napi_throw_error(obj->env_, NULL, "Failed to start uv.poll");
+            return NXT_UNIT_ERROR;
+        }
+
+        port->data = uv_handle;
+        uv_handle->data = ctx;
+    }
+
+    return nxt_unit_add_port(ctx, port);
+}
+
+
+void
+Unit::remove_port(nxt_unit_ctx_t *ctx, nxt_unit_port_id_t *port_id)
+{
+    nxt_unit_port_t  *port;
+
+    port = nxt_unit_find_port(ctx, port_id);
+    if (port == NULL) {
+        return;
+    }
+
+    if (port->in_fd != -1 && port->data != NULL) {
+        uv_poll_stop((uv_poll_t *) port->data);
+
+        delete (uv_poll_t *) port->data;
+    }
+
+    nxt_unit_remove_port(ctx, port_id);
+}
+
+
 napi_value
 Unit::get_server_object()
 {
@@ -320,40 +427,6 @@
 }
 
 
-napi_value
-Unit::emit(napi_value obj, const char *name, size_t name_len, size_t argc,
-           napi_value *argv)
-{
-    napi_value   emitter, return_val, str;
-    napi_status  status;
-
-    status = napi_get_named_property(env_, obj, "emit", &emitter);
-    if (status != napi_ok) {
-        return nullptr;
-    }
-
-    status = napi_create_string_latin1(env_, name, name_len, &str);
-    if (status != napi_ok) {
-        return nullptr;
-    }
-
-    if (argc != 0) {
-        argv[0] = str;
-
-    } else {
-        argc = 1;
-        argv = &str;
-    }
-
-    status = napi_call_function(env_, obj, emitter, argc, argv, &return_val);
-    if (status != napi_ok) {
-        return nullptr;
-    }
-
-    return return_val;
-}
-
-
 napi_status
 Unit::create_headers(nxt_unit_request_info_t *req, napi_value request)
 {
@@ -480,7 +553,7 @@
 napi_value
 Unit::create_socket(napi_value server_obj, nxt_unit_request_info_t *req)
 {
-    napi_value   constructor, return_val;
+    napi_value   constructor, return_val, req_pointer;
     napi_status  status;
 
     status = napi_get_named_property(env_, server_obj, "socket",
@@ -494,6 +567,17 @@
         return nullptr;
     }
 
+    status = napi_create_int64(env_, (uintptr_t) req, &req_pointer);
+    if (status != napi_ok) {
+        return nullptr;
+    }
+
+    status = napi_set_named_property(env_, return_val, "req_pointer",
+                                     req_pointer);
+    if (status != napi_ok) {
+        return nullptr;
+    }
+
     return return_val;
 }
 
@@ -563,27 +647,6 @@
 }
 
 
-void
-Unit::emit_post_data(napi_value request, nxt_unit_request_info_t *req)
-{
-    void         *data;
-    napi_value   req_argv[2];
-    napi_status  status;
-
-    status = napi_create_buffer(env_, (size_t) req->content_length,
-                                &data, &req_argv[1]);
-    if (status != napi_ok) {
-        napi_throw_error(env_, NULL, "Failed to create request buffer");
-        return;
-    }
-
-    nxt_unit_request_read(req, data, req->content_length);
-
-    emit(request, "data", sizeof("data") - 1, 2, req_argv);
-    emit(request, "end", sizeof("end") - 1, 0, nullptr);
-}
-
-
 napi_value
 Unit::response_send_headers(napi_env env, napi_callback_info info)
 {
diff -r 31027fb75905 -r 99103649afea src/nodejs/unit-http/unit.h
--- a/src/nodejs/unit-http/unit.h	Wed Oct 24 16:21:53 2018 +0300
+++ b/src/nodejs/unit-http/unit.h	Wed Oct 31 15:51:51 2018 +0300
@@ -36,13 +36,13 @@
 
     static napi_value create_server(napi_env env, napi_callback_info info);
     static napi_value listen(napi_env env, napi_callback_info info);
+    static napi_value _read(napi_env env, napi_callback_info info);
     static void request_handler(nxt_unit_request_info_t *req);
+    static int add_port(nxt_unit_ctx_t *ctx, nxt_unit_port_t *port);
+    static void remove_port(nxt_unit_ctx_t *ctx, nxt_unit_port_id_t *port_id);
 
     napi_value get_server_object();
 
-    napi_value emit(napi_value obj, const char *name, size_t name_len,
-                    size_t argc, napi_value *argv);
-
     napi_value create_socket(napi_value server_obj,
                              nxt_unit_request_info_t *req);
 
@@ -52,8 +52,6 @@
                                napi_value request,
                                nxt_unit_request_info_t *req, Unit *obj);
 
-    void emit_post_data(napi_value request, nxt_unit_request_info_t *req);
-
     static napi_value response_send_headers(napi_env env,
                                             napi_callback_info info);
 
diff -r 31027fb75905 -r 99103649afea src/nxt_unit.c
--- a/src/nxt_unit.c	Wed Oct 24 16:21:53 2018 +0300
+++ b/src/nxt_unit.c	Wed Oct 31 15:51:51 2018 +0300
@@ -74,7 +74,6 @@
 static nxt_unit_process_t *nxt_unit_process_find(nxt_unit_ctx_t *ctx,
     pid_t pid, int remove);
 static nxt_unit_process_t *nxt_unit_process_pop_first(nxt_unit_impl_t *lib);
-static int nxt_unit_run_once(nxt_unit_ctx_t *ctx);
 static int nxt_unit_create_port(nxt_unit_ctx_t *ctx,
     nxt_unit_port_id_t *port_id, int *fd);
 
@@ -2697,7 +2696,7 @@
 }
 
 
-static int
+int
 nxt_unit_run_once(nxt_unit_ctx_t *ctx)
 {
     int                  rc;
diff -r 31027fb75905 -r 99103649afea src/nxt_unit.h
--- a/src/nxt_unit.h	Wed Oct 24 16:21:53 2018 +0300
+++ b/src/nxt_unit.h	Wed Oct 31 15:51:51 2018 +0300
@@ -196,6 +196,8 @@
  */
 int nxt_unit_run(nxt_unit_ctx_t *);
 
+int nxt_unit_run_once(nxt_unit_ctx_t *ctx);
+
 /* Destroy application library object. */
 void nxt_unit_done(nxt_unit_ctx_t *);
 

@phyllisstein
Copy link
Author

phyllisstein commented Oct 31, 2018

🙌 That patch worked beautifully! I tested it with Koa and Express using native Promises, and with Express and Bluebird, and everything worked just as expected. If it's useful for future testing, you can check out the servers in this Gist: https://gist.github.com/phyllisstein/af8d94962ee48d86652f42c8f74bc266

Thanks so much for supporting this use case---I'm excited to start moving my production Node servers over to Unit this evening.

@nshadrin
Copy link
Contributor

@phyllisstein Thanks for your quick response. Please keep us in the loop on how it goes.

@phyllisstein
Copy link
Author

Will do! I did manage to reproduce a very similar-looking failure when trying to run a Webpack dev server through Unit---the logged error is also "blocked read event," but it's triggered by trying to create a Webpack compiler instance from outside a server middleware.

I threw together a reproduction repo here; there are also some debug logs in there, in case they're useful. Happy to open a new ticket if this seems unrelated, just let me know.

@lexborisov
Copy link
Contributor

@phyllisstein

Thanks for the report!
I work with this.

@lexborisov
Copy link
Contributor

Hi @phyllisstein
I fix this problem (with webpack). Please, try this path:

# HG changeset patch
# User Alexander Borisov <alexander.borisov@nginx.com>
# Date 1541519250 -10800
#      Tue Nov 06 18:47:30 2018 +0300
# Node ID f3e7832fddc836069b7308cd560c3020ee2c98b5
# Parent  85a1832ad45ccd913cc68ef8f9f502f811f42e57
[mq]: unit-lib-path

diff -r 85a1832ad45c -r f3e7832fddc8 src/nodejs/unit-http/http_server.js
--- a/src/nodejs/unit-http/http_server.js	Thu Nov 01 19:10:32 2018 +0300
+++ b/src/nodejs/unit-http/http_server.js	Tue Nov 06 18:47:30 2018 +0300
@@ -72,13 +72,17 @@
             throw new TypeError('Value argument must be string, number, or array');
         }
 
+        if (typeof value === 'number') {
+            value = value + "";
+        }
+
         header_count = 1;
         header_len = Buffer.byteLength(value + "", 'latin1');
     }
 
     this.removeHeader(key);
 
-    this.headers[key] = value + "";
+    this.headers[key] = value;
     this.headers_len += header_len + (header_key_len * header_count);
     this.headers_count += header_count;
 };
diff -r 85a1832ad45c -r f3e7832fddc8 src/nodejs/unit-http/unit.cpp
--- a/src/nodejs/unit-http/unit.cpp	Thu Nov 01 19:10:32 2018 +0300
+++ b/src/nodejs/unit-http/unit.cpp	Tue Nov 06 18:47:30 2018 +0300
@@ -111,6 +111,7 @@
 Unit::create(napi_env env, napi_callback_info info)
 {
     Unit         *obj;
+    napi_ref     ref;
     napi_value   target, cons, instance, jsthis;
     napi_status  status;
 
@@ -135,6 +136,11 @@
             goto failed;
         }
 
+        status = napi_create_reference(env, jsthis, 1, &ref);
+        if (status != napi_ok) {
+            goto failed;
+        }
+
         return jsthis;
     }
 
@@ -149,6 +155,11 @@
         goto failed;
     }
 
+    status = napi_create_reference(env, instance, 1, &ref);
+    if (status != napi_ok) {
+        goto failed;
+    }
+
     return instance;
 
 failed:

@VBart
Copy link
Contributor

VBart commented Jan 15, 2019

All these issues have been fixed with release of Unit 1.7.

@VBart VBart closed this as completed Jan 15, 2019
@phyllisstein
Copy link
Author

Thank you so much for all your hard work, @VBart and @lexborisov! I'm sorry that I didn't come back with feedback about this last patch---I wound up having to pull away from Unit for a bit to focus on other deployment strategies, but now that all of this has landed I look forward to taking it for another spin. ✨

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants
@phyllisstein @VBart @lexborisov @nshadrin and others