Stumped on error with requiring ../encodings

[leanderlee]

I've been stumped by this error a few times, and it's really hard to reproduce because it only happens once on a new install. So in a desperate attempt to glean more information, I'm posting this here to see if someone with a bit more knowledge can help point me in the right direction.

This error seems to be something with iconv-lite failing to require ../encodings but it does exist. What's even more strange is that if you restart the server it works fine thereafter.

Here is the stacktrace of the error:

15:40:48 err! [console] Error: Cannot find module '../encodings'
    at Function.Module._resolveFilename (module.js:326:15)
    at Function.Module._load (module.js:277:25)
    at Module.require (module.js:354:17)
    at require (internal/module.js:12:17)
    at Object.getCodec (/somepath/node_modules/body-parser/node_modules/iconv-lite/lib/index.js:61:27)
    at Object.getDecoder (/somepath/node_modules/body-parser/node_modules/iconv-lite/lib/index.js:118:23)
    at getDecoder (/somepath/node_modules/body-parser/node_modules/raw-body/index.js:44:18)
    at readStream (/somepath/node_modules/body-parser/node_modules/raw-body/index.js:218:15)
    at getRawBody (/somepath/node_modules/body-parser/node_modules/raw-body/index.js:106:12)
    at read (/somepath/node_modules/body-parser/lib/read.js:76:3)
    at jsonParser (/somepath/node_modules/body-parser/lib/types/json.js:121:5)
    at Layer.handle [as handle_request] (/somepath/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/somepath/node_modules/express/lib/router/index.js:312:13)
    at /somepath/node_modules/express/lib/router/index.js:280:7
    at Function.process_params (/somepath/node_modules/express/lib/router/index.js:330:12)
    at next (/somepath/node_modules/express/lib/router/index.js:271:10)
    at expressInit (/somepath/node_modules/express/lib/middleware/init.js:33:5)
    at Layer.handle [as handle_request] (/somepath/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/somepath/node_modules/express/lib/router/index.js:312:13)
    at /somepath/node_modules/express/lib/router/index.js:280:7
    at Function.process_params (/somepath/node_modules/express/lib/router/index.js:330:12)
    at next (/somepath/node_modules/express/lib/router/index.js:271:10)
    at query (/somepath/node_modules/express/lib/middleware/query.js:49:5)
    at Layer.handle [as handle_request] (/somepath/node_modules/express/lib/router/layer.js:95:5)
    at trim_prefix (/somepath/node_modules/express/lib/router/index.js:312:13)
    at /somepath/node_modules/express/lib/router/index.js:280:7
    at Function.process_params (/somepath/node_modules/express/lib/router/index.js:330:12)
    at next (/somepath/node_modules/express/lib/router/index.js:271:10)
    at Function.handle (/somepath/node_modules/express/lib/router/index.js:176:3)
    at EventEmitter.handle (/somepath/node_modules/express/lib/application.js:173:10)
    at Server.app (/somepath/node_modules/express/lib/express.js:38:9)
    at Server.<anonymous> (/somepath/node_modules/socket.io/node_modules/engine.io/lib/server.js:434:22)
    at Server.<anonymous> (/somepath/node_modules/socket.io/lib/index.js:260:16)
    at emitTwo (events.js:87:13)
    at Server.emit (events.js:172:7)
    at HTTPParser.parserOnIncoming [as onIncoming] (_http_server.js:528:12)
    at HTTPParser.parserOnHeadersComplete (_http_common.js:88:23)
  EventEmitter.logerror [console] (application.js:629)
    at Console.error (/somepath/baymax.bundle.js:160:3265)
    at EventEmitter.logerror (/somepath/node_modules/express/lib/application.js:629:43)
    at Immediate.immediate._onImmediate (timers.js:445:18)
    at processImmediate [as _immediateCallback] (timers.js:383:17)

[ZapRowsdower910]

I just encountered this in an expressjs application after upgrading from node 4.2 to 6.6.0. After upgrading node, I removed my node_modules folder and ran a fresh 'npm install'. First startup seemed healthy until posting a form to the server where I saw this issue. As mentioned by @leanderlee restarting the service seemed to fix it.

[ashtuchkin]

Still cannot reproduce it :( Tried the upgrade method you described and it worked without any errors..

Let me know if you're able to consistently reproduce it.

[Marak]

Issue is due to changing the current working directory of node.js process after process starts and then you attempt to perform method using iconv-lite. The lazy require breaks since it's no longer in the same relative path. Same if node_modules somehow disappears after process start.

I think I found the solution.

Try changing:

iconv.encodings = require("../encodings");

to

iconv.encodings = require("iconv-lite/encodings");

https://github.com/ashtuchkin/iconv-lite/blob/master/lib/index.js#L61

[dbussert]

I can reliably recreate this error in our test environment, we deploy node and mode_module updates packaged into an rpm, and in our latest version, our code is crashing on body parsing due to its use of this library. restarting our node service fixes this issue, it only happens right after we deploy the rpm.

[Marak]

@dbussert Did you see my comment?

[ashtuchkin]

Guys I need your help here. I don't have an environment to reproduce it, so I'm counting on you to isolate the exact requirements for this to happen.

I'm also not fond of changing that line to iconv.encodings = require("iconv-lite/encodings"); because that is a workaround for require() bug - it should be fixed on their side. By specification, require should work relative to the caller .js file and it's a much larger issue if it doesn't.

[Marak]

@ashtuchkin -

This isn't something which requires you setup a reproducible environment to isolate or fix the bug.

It seems to be simple. Looking at https://github.com/ashtuchkin/iconv-lite/blob/master/lib/index.js#L61 , we can see that we have a "lazy require" statement.

In other words, we have a require statement which isn't being executed until getCodec function is executed. This is not a bug in require(). There are many reasons and conditions which could cause a lazy require statement to fail.

In the case I hit ( a production service serving millions of requests ), the Node.js process was being chroot to a new directory after the process started. This means that the relative path of ../encodings is no longer valid, hence the errors. Generally, it's not safe to do a lazy require of modules.

Is there a reason that ../encodings.js file is being loaded lazily in getCodec? Could it be required outside the function scope?

Also, you could probably replicate the bug using https://www.npmjs.com/package/chroot library.

[ashtuchkin]

Thanks for the extended explanation, @Marak.

Generally, it's not safe to do a lazy require of modules.

It looks to me that generally, it's not safe to do a chroot of a node process, because node's module caching has unexpected results for dynamic requires. Are you sure other libraries/modules don't use it? It's a perfectly valid mode of loading modules in node.js, as far as I know.

Is there a reason that ../encodings.js file is being loaded lazily in getCodec?

Yes, it's an explicit optimization of startup time. Encodings tree is large and can take several hundred ms to load. I don't want to impose this tax on all projects indirectly requiring iconv-lite because they might not use (or even know about) it at all.

I still don't know why it works the second time for @dbussert - module caching should not depend on that.

[Marak]

@ashtuchkin -

Lazy loading of Node.js modules is not a best practice and can cause several issues. You should understand that require is a synchronous and blocking statement. The same 100ms you are saving on initial load time will now be 100ms of blocked process time when getCodec is first called. I could go on and on. I won't. You are wrong, sorry.

Regardless, I understand the need for optimization on start time. It's a trade-off you have to make. Based on what I see here, the majority of users will never experience this require failing issue and will benefit from the optimized start time. HOWEVER, some users are experiencing this issue and I'm telling you exactly why it's happening.

You should either figure out a fix, or tell us you will not fix it. I already proposed the solution we used in production. What none of us need here is reasons why you don't think this is broken.

Cheers.

[ashtuchkin]

Dear @Marak,

I'm yet to find evidence that others are experiencing the same issue as you are. All the other people in this thread have a situation where a restart "fixes" the problem, which should not happen with a chroot. Also I haven't seen any mention of chroot other than from you. So, I'm still gathering information about that case and would prefer you stop interfering and going personal about it. There's no need to preach about best practices, tell me what I should do, or talk like you represent all the other people in this thread.

As for your particular problem - no, I won't fix it for you. The core reason you have this problem is you built a system based on a subtly incorrect assumption that the node module system works correctly after a chroot. This subtle incorrectness showed itself when you started using iconv-lite, but it has potential to show for other modules as well. You cannot assume that other modules won't use a valid system interface because you think it's "not a best practice". I'm glad you found a workaround for your particular system, but 1) it's not guaranteed to work for other people, and 2) you'll need to find similar workarounds for other libraries/modules. I would've recommended to stop relying on the assumption above and try to fix your system in a more general way, like using a separate process to do the chroot and only start your original node process after that, but I don't have enough context about your system.

To be clear, I'm not being stubborn about making the change you suggested. I'm not doing that because:

1. As I said earlier, I don't have evidence that this what's actually happening for the OP and other people in this thread.
2. Each part of the current solution is there for a good reason:
   1. Dynamic require provides the dont-pay-if-you-dont-use guarantee for users with regards to startup time, as we discussed previously.
   2. Relative require path guarantees that I'm requiring file from the same exact module. As you might already know, there can be several versions of a module installed in a node_modules folder and I have no idea which one of them will be resolved to a top-level 'iconv-lite'. I hope I don't have to explain why this requirement is important.

[Marak]

Have you considered what is going to happen if someone is running a webserver with 1000s of requests per second and then getCodec method is called for the first time? I believe all requests will block until encodings file completes load.

I hit this problem ( of not being able to find encodings file ), found the solution, and posted it here. You want to lazy require a huge file with a relative path, go for it. Every-time anyone hits any environment issue with express where node_modules is not where it's suppose to be after process start is going to google and find this Github Issue. It's why you are seeing a variety of issues reported here with seemingly different sources and behaviors...

[jcreamer898]

The lazy loading also seems to be causing an issue in other libraries... jestjs/jest#2605

[kleggas]

I got the same problem as @Marak is describing, and it does not solve if I restart. His fix worked for me.
And I agree with @Marak. Instead of excusing this behaviour, treat it as the bug it is and fix, please.

[vernondegoede]

I'm experiencing the same issue when executing a script within my sandboxed test environment (Jest) which uses iconv-lite as a dependency.

When I'm not lazy-loading encodings/index.js (but instead requiring everything directory at the top of the module) everything works fine for me.

The initial reason for lazy-loading this module was because of speed issues, which were fixed in PR #26.

I ran this script twice (both using lazy-loading and without) and got the following results:

With lazy-loading:

❯ node -e "require('./lib/index')"  0.18s user 0.02s system 98% cpu 0.204 total

Without lazy-loading (changed iconv.encodings = require('../encodings') at the top of the file):

❯ node -e "require('./lib/index')"  0.18s user 0.02s system 98% cpu 0.204 total

The results seem to be exactly the same. I'm not sure if something changed within Node itself, or if I'm doing something wrong, but if this those stats are correct there would be no reason to lazy-load the encodings anyway.