Excessive npm log output in 4.x
FrederikNJS opened this issue · 28 comments
When running NPM in the 4.x version of the docker image, the image runs with
ENV NPM_CONFIG_LOGLEVEL info
Is there any reason why this is not "warn" as is usually the default?
The log output is enough for Travis-CI to complain that the log output is too long.
Yes, here is my rationale for changing this in the iojs Docker Image a while back: nodejs/docker-iojs#36
We've recently run into this excessive output when we started using node 4.2.x containers. The change looks like it goes back to the initial prep work for node 4.x images done by @chorrell (see e763a10).
Personally, it seems undesirable to override any defaults here. The default loglevel in npm is "warn", and to have it overridden to be "info" is unexpected and requires us to override it again in our own Dockerfiles.
That's a fair point.
I'm fine with removing the loglevel setting if everyone else is.
Thoughts from @nodejs/docker team?
I disagree. npm operates under the assumption that you can always get to the npm log file.
Having read the docker-iojs PR that @Starefossen links to above, I would still advocate for user education in the case of a failed package installation over dumping unnecessary information into the CI logs of the overwhelming majority of docker build / docker run jobs in the wild.
At least document clearly how you can get the default behaviour back. Simple "npm config set loglevel warn" did not work for me, because the NPM_CONFIG_LOGLEVEL set in this image was overriding it. Instead, to get the default log level of "warn" back, you need to add:
ENV NPM_CONFIG_LOGLEVEL warn
to your own Dockerfile.
@Starefossen I'm 👍 on warn since npm-debug.log will be lost when the container stops.
We should document possible workarounds for places where this may not be ideal.
For example: npm install --loglevel=warn > /var/log/npm.log 2>&1 || cat /var/log/npm.log && false will only print the log if the install fails.
+1 for removing this setting and using npm's default behavior.
From long experience with linux, c, and makefiles you want your builds and installs to be as verbose as possible so that you could have a propper log to work with when things fail. Since almost all of the npm stuff is network dependent, and just recently added consistent unpacking, you are not guaranteed that things will fail the same way next time you run (with a more verbose log level).
I believe this is just as true for Docker since often you do not have access to the npm.log, and many containers are run with docker run --rm which deletes the container after it exits regardless of the exit code.
I also do not buy the argument about not being the default setting and hence it should not be in the image. We must be free to optimise the settings for the Docker runtime and the ways Docker is used different form other platforms.
From my investigation this is only really an issue on Travis CI which has a 4MB output limit travis-ci/travis-ci#1382.
@HackAttack could you elaborate why you would like to change the npm log level?
We must be free to optimise the settings for the Docker runtime and the ways Docker is used different form other platforms.
This goes against what I want as a Docker user. I want things to work the same, not differently. If certain things behave differently in the Docker environment than outside (in this case, the output from npm commands), that violates the principle of least astonishment and works against my use case for running Docker. If I want verbose logs I can specify the setting myself in my Dockerfile, but I expect the official image to have the same default behavior as the software itself, and this setting violates that expectation.
I also don't think it's appropriate to assume that a) verbose logs would always be desired on CI servers, or b) Docker is only or primarily being run on CI servers. I run Docker locally and it is unpleasant to have these logs in my console when I didn't ask for them.
I don't have a preference on which log verbosity we use.
Would it be an improvement to have a line like:
ENV NPM_CONFIG_LOGLEVEL info # increase verbosity of log. NPM defaults to warn
So that it is obvious that is what needs to be changed if the user wants default behavior?
Instead of the current ONBUILD RUN npm install --loglevel info
This goes against what I want as a Docker user. I want things to work the same, not differently. If certain things behave differently in the Docker environment than outside (in this case, the output from npm commands), that violates the principle of least astonishment and works against my use case for running Docker.
The purpose of Docker is consistency, not similarity to the host OS. Unless you are running Debian on your host machine the Node.js application in the Docker Container will never behave exactly the same as running it on your local machine, but it will behave the same each time you run the container (hence consistency).
The purpose of Docker is consistency, not similarity to the host OS. Unless you are running Debian on your host machine the Node.js application in the Docker Container will never behave exactly the same as running it on your local machine
When he uses the phrase "same not different", I don't believe that @HackAttack was advocating that a Docker container should behave in any way similar to the local host environment on which it's running. I interpreted his sentiment to be similar to my own. If I download the Docker image for a particular environment (Ubuntu 12.04, node 4.2.0, etc), I would expect that image to behave as similarly as possible to a clean instantiation of that environment, including all default behaviors, packages, configurations, etc. The consistency that you speak of is indeed a valuable benefit of Docker, but I would describe Docker's primary purpose as specificity; as a Docker user I can be specific about what base environment my software runs in, and then I can be specific about how I augment that environment to suit my specific needs. In my opinion, Docker images should aim to be specific in what they are providing. node:4.2.2 indicates that I am getting node v4.2.2, not node v4.2.2 with a few configuration changes that we believe will benefit you.
Thanks @jackwanders for making such a clear case.
I am also convinced that it is not up to the docker packaging of node to decide to override the default settings of a node installation.
Let's note that the original PR applied only to theonbuild image.
The onbuild is the most opinionated image that we provide. We have taken a number of decisions in this image for our consumers: where the application code is located in the image, the fact that we install the dev dependencies and the production dependencies etc.
Hence +1 removing ENV NPM_CONFIG_LOGLEVEL info from the slim and base flavors. We can keep our customizations in the onbuild flavor.
More importantly, I enjoy working with @pesho, @Starefossen and the rest of the community on the docker packaging of node: I don't mind keeping things as they are and agreeing to disagree :)
Thanks for your input @hmalphettes. I too enjoy working with the Node.js Docker Working group and the various users of the Node.js Docker Image. The fact that we are having this discussion means that we have people who care about the project - and that is a good thing.
I think there are two discussions here. One is the actual value of the NPM_CONFIG_LOGLEVEL, and the broader discussion is how much the Node.js Docker Image can differ from a default local Node.js installation.
I think of Docker more similar to package managers than to a binary distribution. Most package managers have their own conventions according to their distribution target which may converge from the source such as where to put configuration files; security defaults; and even dependencies; and that is acceptable.
The problem is that Docker is a fairly new platform and the conventions and expectations for Docker Images have just started forming. Take a look at the various official Docker Images in the Docker Registry and you will see that most of them do some customizing according what they believe are best defaults for the Docker runtime environment and Docker Image use cases.
With regards to the NPM_CONFIG_LOGLEVEL the Node.js Docker Image should strive not to introduce breaking changes with regards to the corresponding Node.js version installed in the image. I have tried to highlight the reasons behind the change which I think are reasonable.
However if the @nodejs/docker Working Group is more or less evenly divided between keeping the current loglevel and reverting back to the default loglevel I think the safest option is to revert.
So, I arrived here after noticing that npm config set loglevel warn didn't work. Surprise!
I don't think of myself as a npm expert, so I not even considered that an environment variable
could be forcibly overriding that configuration.
I have been using Node + npm since 2012,and I never really made much configurations to npm.
Now imagine the frustration of someone who's just starting, they're very likely to go to StackOverflow
(in which case such developer may get even more frustrated because of how StackOverflow goes
nowadays) before reaching this issue like I did - in the case they don't like the assumption that info is a good default for logging, of course.
If people at @nodejs/docker decide the best log level is info, at least make it more obvious to
override with a simple npm config set command.
Just my 2 cents.
I'm 👍 on documenting this behaviour, and still 👎 on reverting the default.
While I understand this can be undesirable on CI servers, I think the primary concern here is the average developer running this locally. A failed npm install inside the Docker container will instruct you to refer to the npm log file for more info, but that file gets nuked when the layer fails to build. CI/CD teams can
I also understand where your pains stem from @gustavohenke but, in the same light, my hypothesis is that giving too much information up front and feeling lost trying to quiet it down is a better problem than having no information upfront and feeling lost trying to figure out why your image isn't building.
Working on a PR to explain the output verbosity and how one could reset it to the warn if you would like to do so.
Maybe a way to make everybody happy is to provide a way to mount an external npm config file
If you have a file that you use that has all the settings you are used to, you could mount it, if not, the defaults are used.
This would address the environment variable taking precedence.
I think you can already do this by copying in an npmrc file.
For me the issue is not clarity around how the settings are changed, but rather the fact that I have to change them at all to restore what is documented to be npm’s default behavior. In my opinion, official images for software packages should do only what’s necessary to get that software running—no more, no less—and not also make opinionated configuration tweaks.
This was unexpected behaviour for us, took us a while to track it down.
From @mhart on twitter:
Wanna pull some files out of that container you just exited?
docker export | tar -cz --include='somedir/*' @- > somedir.tar.gz
https://twitter.com/hichaelmart/status/735219853926223872
This might let us explore reverting back to normal log levels and documenting this solution for recovering .npm-debug from failed builds.
Yeah, that seems really useful and maybe something we should document as apposed to #113 and then drop the excessive logging.
Just double check before you do – my tweet was aimed at cases for when you've run and exited a container (not during a build)
From long experience with linux, c, and makefiles you want your builds and installs to be as verbose as possible so that you could have a proper log to work with when things fail.
@Starefossen The "warn" log level already outputs useful information when things fail. It is much harder to tell if thing succeeded and why things failed when I have to sift through the excessive output of the "info" logging level. I am having a hard time finding my own logging output, which makes false positives much harder to catch.
@Starefossen @retrohacker You can easily retrieve files from a stopped docker container. Docker also keeps the stopped container if a build fails. So getting the npm-debug.log file from the container after a failed build should not be a problem.
Here an working workflow for getting npm-debug.log out of a failed build:
> docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
> docker images
REPOSITORY TAG IMAGE ID CREATED SIZE
node 7.3.0 d1699fb7d2bf 18 hours ago 659.8 MB
> ls
Dockerfile
> cat Dockerfile
FROM node:7.3.0
ENV NPM_CONFIG_LOGLEVEL warn
RUN npm install this-package-should-not-exist
> docker build .
Sending build context to Docker daemon 2.048 kB
Step 1 : FROM node:7.3.0
---> d1699fb7d2bf
Step 2 : ENV NPM_CONFIG_LOGLEVEL warn
---> Running in e73cbd3342a2
---> da9b250b0b65
Removing intermediate container e73cbd3342a2
Step 3 : RUN npm install this-package-should-not-exist
---> Running in 11f68b09bbfd
npm ERR! Linux 4.4.0-53-generic
npm ERR! argv "/usr/local/bin/node" "/usr/local/bin/npm" "install" "this-package-should-not-exist"
npm ERR! node v7.3.0
npm ERR! npm v3.10.10
npm ERR! code E404
npm ERR! 404 Registry returned 404 for GET on https://registry.npmjs.org/this-package-should-not-exist
npm ERR! 404
npm ERR! 404 'this-package-should-not-exist' is not in the npm registry.
npm ERR! 404 You should bug the author to publish it (or use the name yourself!)
npm ERR! 404
npm ERR! 404 Note that you can also install from a
npm ERR! 404 tarball, folder, http url, or git url.
npm ERR! Please include the following file with any support request:
npm ERR! /npm-debug.log
The command '/bin/sh -c npm install this-package-should-not-exist' returned a non-zero code: 1
> docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
11f68b09bbfd da9b250b0b65 "/bin/sh -c 'npm inst" 13 seconds ago Exited (1) 10 seconds ago sharp_lichterman
> docker cp 11f68b09bbfd:/npm-debug.log .
> ls
Dockerfile npm-debug.log
> cat npm-debug.log
0 info it worked if it ends with ok
1 verbose cli [ '/usr/local/bin/node',
1 verbose cli '/usr/local/bin/npm',
1 verbose cli 'install',
1 verbose cli 'this-package-should-not-exist' ]
2 info using npm@3.10.10
3 info using node@v7.3.0
...
You could also use docker cp 11f68b09bbfd:/npm-debug.log - to output the contents directly to stdout or pipe it into some other command.