Start offline after webpack is compiled

[sime]

This is a Bug Report

Description

• What went wrong?
  Building of webpack is async and is often completed after offline has started. This is limiting as the --exec parameter queues a script to start firing requests against the application which is not yet built.

• What did you expect should have happened?

1. sls offline start
2. start webpack build
3. end webpack build
4. start offline plugin
5. exec script
6. stop offline plugin

• What was the config you used
  `./node_modules/serverless/bin/serverless offline -c start --exec "yarn test-system"

• What stacktrace or error message from your provider did you see?
  n/a

Additional Data

• Serverless-Webpack Version you're using: 3.1.2
• Webpack version you're using: 3.8.1
• Serverless Framework Version you're using: 1.24
• Operating System: Linux/Mac
• Stack Trace:

Serverless: GET /v1/restaurants/1/onboarding (λ: getOnboarding)

Serverless: Error while loading getOnboarding

[ 'Error: Serverless-offline: handler for \'getOnboarding\' is not a function',
  'at Object.createHandler (/home/travis/build/deliveryhero/rps-kyc/node_modules/serverless-offline/src/functionHelper.js:38:13)',
  'at handler (/home/travis/build/deliveryhero/rps-kyc/node_modules/serverless-offline/src/index.js:499:40)',
  'at Object.internals.handler (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/handler.js:96:36)',
  'at request._protect.run (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/handler.js:30:23)',
  'at internals.Protect.run (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/protect.js:64:5)',
  'at exports.execute (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/handler.js:24:22)',
  'at each (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/request.js:384:16)',
  'at iterate (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:36:13)',
  'at done (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:28:25)',
  'at internals.Auth._authenticate (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/auth.js:210:16)',
  'at internals.Auth.authenticate (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/auth.js:202:17)',
  'at each (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/request.js:384:16)',
  'at iterate (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:36:13)',
  'at done (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:28:25)',
  'at internals.state (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/route.js:357:16)',
  'at each (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/request.js:384:16)',
  'at iterate (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:36:13)',
  'at Object.exports.serial (/home/travis/build/deliveryhero/rps-kyc/node_modules/items/lib/index.js:39:9)',
  'at internals.Request._lifecycle (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/request.js:387:11)',
  'at internals.Request._execute (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/request.js:302:21)',
  'at Domain.request._protect.enter (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/connection.js:261:25)',
  'at Domain.run (domain.js:221:14)',
  'at internals.Protect.enter (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/protect.js:80:17)',
  'at Server.<anonymous> (/home/travis/build/deliveryhero/rps-kyc/node_modules/hapi/lib/connection.js:259:30)',
  'at emitTwo (events.js:106:13)',
  'at Server.emit (events.js:191:7)',
  'at HTTPParser.parserOnIncoming [as onIncoming] (_http_server.js:546:12)' ]
Serverless: Replying error in handler

[HyperBrain]

@sime Thanks for raising the issue.

Can you check in the serverless.yml that you have put the webpack plugin before the offline plugin?

The webpack compile is async, but the plugin's hook will only return, if the compile has been finished, not before. We hook

      'before:offline:start': () => BbPromise.bind(this)
        .then(this.prepareOfflineInvoke)
        .then(() => this.serverless.pluginManager.spawn('webpack:compile'))
        .then(this.wpwatch),

      'before:offline:start:init': () => BbPromise.bind(this)
        .then(this.prepareOfflineInvoke)
        .then(() => this.serverless.pluginManager.spawn('webpack:compile'))
        .then(this.wpwatch),

what means that the compile has been finished when offline is invoked. Only when the webpack:compile lifecycle terminated, offline will get control.

If your plugin order is correct, it might be an issue in the offline plugin (especially the exec functionality) and it's integration into the Serverless lifecycle.

[sime]

In regards to plugin order, yes, the webpack plugin is before the offline plugin.

I can definitely confirm according to STDOUT the webpack is not complete by the time the offline server has started.

[HyperBrain]

Then it looks like an issue either in Serverless or the offline plugin. I'll check how the hooks are called there in case you use exec. The webpack plugin cannot do more than hook and make sure that it returns from its hook, as soon as everything has been finished.

If the compile would not wait, all other functionality like package and deploy would not work at all. It even works now with "serverless run" (PR pending) which also depends on the compilation.

I will report back here.

[HyperBrain]

@sime Can you execute the offline with SLS_DEBUG=* ./node_modules/serverless/bin/serverless offline start --exec "yarn test-system" --verbose and post the output.

With the 2 additional settings it should log exactly which hook and command is invoked in which order. that might help to find the reason much easier.

BTW: I just saw the -c in your command line. imo that's wrong as start is the command for offline.

[sime]

@HyperBrain Log is available here: https://gist.github.com/sime/53c95c49e495d61d824958f0b5feaaab

[HyperBrain]

@sime Thank you. I analyzed the logs.
The initial startup is correct:

Serverless: Invoke offline:start
Serverless: WARNING: More than one matching handlers found for 'handler'. Using 'handler.js'.
Serverless: WARNING: More than one matching handlers found for 'handler'. Using 'handler.js'.
Serverless: WARNING: More than one matching handlers found for 'handler'. Using 'handler.js'.
Serverless: WARNING: More than one matching handlers found for 'handler'. Using 'handler.js'.
Serverless: Bundling with Webpack...
Time: 5512ms
         Asset     Size  Chunks                    Chunk Names
    handler.js  4.86 MB       0  [emitted]  [big]  handler
handler.js.map  6.41 MB       0  [emitted]         handler
[...]
    + 1105 hidden modules

WARNING in ./node_modules/express/lib/view.js
81:13-25 Critical dependency: the request of a dependency is an expression
[...]
Serverless: Watching with Webpack...
Serverless: Starting Offline: test/eu-west-1.

That means that the compile is done, and then the offline plugin is started.

Further down in the logs it seems that webpack triggers a watch compile (as if a source changed in the source folder tree). That's where it eventually breaks (the compile outputs with "HASH"). Does the test modify sources?

Regarding the warnings: How do you define the entry property in your webpack config, and do you have the handlers in your serverless.yml correctly defined with the relative path to the handlers?
We should first verify that the project setup is correct (especially the handlers and the entries), because that might also cause this issue.

Do you use "node-externals"? The critical dependency error looks also strange.
Best would be if I could have a look at the webpack.config.js and the function definitions of the serverless.yml

[sime]

Only a single value in slsw.lib.entries, which are aligned with all the handers in serverless.yml:

 { handler: './handler.js' }

I do agree it looks like a watch has been triggered, oddly the value of the HASH is the same.

So I have disabled watch for now. New log: https://gist.github.com/sime/ce2ca622226eba81ed95b5611e987d81

[HyperBrain]

The entry looks odd too. Normally there should be as many as there are functions, or do you only have one handler that serves all endpoints and functions?

You should define your handlers in serverless.yml as handler: src/mysubdir/handler.myhandlefunc, set entry: slsw.lib.entries and output: filename: '[name].js' in your webpack config. Otherwise the handlers will overwrite each other and might mess up the compile. These settings will make sure that the compiled handlers are distinct and the compiled folder layout is the same as it would have been without the webpack plugin.

[sime]

Yes it does look odd, we have 4 functions using the same handler. serverless-http takes care of this for us.

Though the problem doesn't persist if we put a 'sleep 10' in the --exec parameter.

[HyperBrain]

I'm pretty sure that the function setup triggers the recompiles as something alters the source tree and an included file. We work a lot with serverless-offline and watch mode and never encountered the problem. Of couse you have to wait until the function is actually recompiled before you can issue a local API call to the handler again. Watch mode is primarily intended for local development, where a developer changes a file and tests afterwards, but not for automated tools.

Regardless if the source changes are a bug somewhere, I would propose to solve the issue by adding a --webpack-no-watch switch to the plugin. Right now the plugin enables watch mode unconditionally with the offline plugin, which is not good for automated systems. Such a switch would disable watch mode and let automated systems run correctly.
However the default must be kept (enable watch mode without switch) to not break existing systems.

@sime What do you think of such a solution?

[sime]

Yes, your proposal is sound.

Sadly, having disabled watch mode directly (watch: false) in webpack.config.js directly saw no noticeable difference in my testing.

[HyperBrain]

Sadly, having disabled watch mode directly (watch: false) in webpack.config.js directly saw no noticeable difference in my testing.

Yeah. Unfortunately that's not supported, because everything is managed with command line switches in this area (like --webpack-use-polling to switch to poll mode instead of filesystem events if you use the plugin in docker)

I will prepare a PR for the new switch then you can test it.

[HyperBrain]

While working on the fix I discovered that this is an overlay of 2 problems:

When entering watch mode, webpack does a fresh compile, which was the first rebuild that you've seen after (better during) offline started. I'm fixing that by only using watch instead of the standard compile as it will do the compile anyway and wait for the first one to complete.

Additionally add the no watch switch to cover the automated test scenario.

[HyperBrain]

I will create the PR now - you can test it then again with and without the --webpack-no-watch switch.

However, invoke local --watch suffers from the same startup problem (double compile) and I will fix that too. Just saw that this is not a problem for local invoke because that waits for the invoke to finish before it starts the watch mode.