Skip to content

The container exits immediately with operation not permitted error #342

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.

Sign up for GitHub

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

Jump to bottom
Closed
dev-nicelee opened this issue Mar 27, 2019 · 6 comments
Closed

The container exits immediately with operation not permitted error #342

dev-nicelee opened this issue Mar 27, 2019 · 6 comments
Labels
question Usability question, not directly related to an error with the image

Comments

@dev-nicelee
Copy link

dev-nicelee commented Mar 27, 2019 •
edited
Loading

I've been trying to run mongodb docker by shelljs.

In a shelljs script to exceute shell script has codes to create multiple docker containers including mongodb

But, there's a permission error after creating multiple other dockers.

Checking what was happening in the docker is literally impossible since mongodb is exits immediately..

But, if I restart the exited container again in terminal, it works fine and read/write from another container is totally fine..

Here's entire logs about this issue.

2019-03-27T00:12:32.402+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=184589814fd7
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] db version v4.0.7
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] git version: 1b82c812a9c0bbf6dc79d5400de9ea99e6ffa025
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] modules: none
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] build environment:
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     distarch: x86_64
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] options: { net: { bindIpAll: true } }
2019-03-27T00:12:32.409+0000 W STORAGE  [initandlisten] Detected unclean shutdown - /data/db/mongod.lock is not empty.
2019-03-27T00:12:32.418+0000 I STORAGE  [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2019-03-27T00:12:32.423+0000 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2019-03-27T00:12:32.425+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=5484M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2019-03-27T00:13:10.575+0000 I STORAGE  [initandlisten] WiredTiger message [1553645590:575096][1:0x7fcc2b43fa40], txn-recover: Main recovery loop: starting at 67/3712 to 68/256
2019-03-27T00:13:10.660+0000 I STORAGE  [initandlisten] WiredTiger message [1553645590:660124][1:0x7fcc2b43fa40], txn-recover: Recovering log 67 through 68
2019-03-27T00:13:12.020+0000 I STORAGE  [initandlisten] WiredTiger message [1553645592:20636][1:0x7fcc2b43fa40], txn-recover: Recovering log 68 through 68
2019-03-27T00:13:12.074+0000 I STORAGE  [initandlisten] WiredTiger message [1553645592:74319][1:0x7fcc2b43fa40], txn-recover: Set global recovery timestamp: 0
2019-03-27T00:13:12.130+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] 
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] 
2019-03-27T00:13:12.868+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2019-03-27T00:13:12.878+0000 I NETWORK  [initandlisten] waiting for connections on port 27017
2019-03-27T00:13:13.047+0000 I FTDC     [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2019-03-27T00:16:00.179+0000 I NETWORK  [listener] connection accepted from 172.17.0.1:48380 #1 (1 connection now open)
2019-03-27T00:16:00.193+0000 I NETWORK  [conn1] received client metadata from 172.17.0.1:48380 conn1: { driver: { name: "nodejs", version: "3.1.13" }, os: { type: "Darwin", name: "darwin", architecture: "x64", version: "18.2.0" }, platform: "Node.js v10.15.1, LE, mongodb-core: 3.1.11" }
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] WiredTiger error (1) [1553645760:222801][1:0x7fcc2b43e700], file:index-8--5221266744114051756.wt, WT_SESSION.open_cursor: __posix_open_file, 715: /data/db/index-8--5221266744114051756.wt: handle-open: open: Operation not permitted Raw: [1553645760:222801][1:0x7fcc2b43e700], file:index-8--5221266744114051756.wt, WT_SESSION.open_cursor: __posix_open_file, 715: /data/db/index-8--5221266744114051756.wt: handle-open: open: Operation not permitted
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] Failed to open a WiredTiger cursor: table:index-8--5221266744114051756
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] This may be due to data corruption. Please read the documentation for starting MongoDB with --repair here: http://dochub.mongodb.org/core/repair
2019-03-27T00:16:00.224+0000 F -        [conn1] Fatal Assertion 50882 at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 143
2019-03-27T00:16:00.224+0000 F -        [conn1] 

***aborting after fassert() failure
@wglambert wglambert added the question Usability question, not directly related to an error with the image label Mar 27, 2019
@wglambert
Copy link

What is the specific permission error, and what are the docker logs on the container.

This looks to be an issue with your environment or perhaps volumes you're mounting in the container with improper permissions.

@dev-nicelee
Copy link
Author

dev-nicelee commented Mar 28, 2019 •
edited
Loading

@wglambert docker logs is exactly the same as I attached above the issue. I suppose that one of suspicious reasons is the environment like you said.. I've just left my environment below..!

- OS : macOS Mojave 10.14.3
- Macintosh HD : APFS Volume
- Docker version 18.09.2, build 6247962
- Mongodb docker version : latest

Does the docker not fully support mounting for MacOS?
Because it never occurs the error in Ubuntu..

Thanks a lot @wglambert !

@dev-nicelee
Copy link
Author

Here's the progress what I've been working on this so far.

Issue

  1. Running mongo docker : docker run -d -p 27017:27017 --name mongodb -v $(pwd)/data/db:/data/db mongo
  2. Connecting via mongoose in nodejs server
  3. mongo container exits directly with logs below
2019-03-27T00:12:32.402+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=184589814fd7
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] db version v4.0.7
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] git version: 1b82c812a9c0bbf6dc79d5400de9ea99e6ffa025
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] modules: none
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] build environment:
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     distarch: x86_64
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2019-03-27T00:12:32.405+0000 I CONTROL  [initandlisten] options: { net: { bindIpAll: true } }
2019-03-27T00:12:32.409+0000 W STORAGE  [initandlisten] Detected unclean shutdown - /data/db/mongod.lock is not empty.
2019-03-27T00:12:32.418+0000 I STORAGE  [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2019-03-27T00:12:32.423+0000 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2019-03-27T00:12:32.425+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=5484M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2019-03-27T00:13:10.575+0000 I STORAGE  [initandlisten] WiredTiger message [1553645590:575096][1:0x7fcc2b43fa40], txn-recover: Main recovery loop: starting at 67/3712 to 68/256
2019-03-27T00:13:10.660+0000 I STORAGE  [initandlisten] WiredTiger message [1553645590:660124][1:0x7fcc2b43fa40], txn-recover: Recovering log 67 through 68
2019-03-27T00:13:12.020+0000 I STORAGE  [initandlisten] WiredTiger message [1553645592:20636][1:0x7fcc2b43fa40], txn-recover: Recovering log 68 through 68
2019-03-27T00:13:12.074+0000 I STORAGE  [initandlisten] WiredTiger message [1553645592:74319][1:0x7fcc2b43fa40], txn-recover: Set global recovery timestamp: 0
2019-03-27T00:13:12.130+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] 
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2019-03-27T00:13:12.548+0000 I CONTROL  [initandlisten] 
2019-03-27T00:13:12.868+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
2019-03-27T00:13:12.878+0000 I NETWORK  [initandlisten] waiting for connections on port 27017
2019-03-27T00:13:13.047+0000 I FTDC     [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2019-03-27T00:16:00.179+0000 I NETWORK  [listener] connection accepted from 172.17.0.1:48380 #1 (1 connection now open)
2019-03-27T00:16:00.193+0000 I NETWORK  [conn1] received client metadata from 172.17.0.1:48380 conn1: { driver: { name: "nodejs", version: "3.1.13" }, os: { type: "Darwin", name: "darwin", architecture: "x64", version: "18.2.0" }, platform: "Node.js v10.15.1, LE, mongodb-core: 3.1.11" }
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] WiredTiger error (1) [1553645760:222801][1:0x7fcc2b43e700], file:index-8--5221266744114051756.wt, WT_SESSION.open_cursor: __posix_open_file, 715: /data/db/index-8--5221266744114051756.wt: handle-open: open: Operation not permitted Raw: [1553645760:222801][1:0x7fcc2b43e700], file:index-8--5221266744114051756.wt, WT_SESSION.open_cursor: __posix_open_file, 715: /data/db/index-8--5221266744114051756.wt: handle-open: open: Operation not permitted
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] Failed to open a WiredTiger cursor: table:index-8--5221266744114051756
2019-03-27T00:16:00.224+0000 E STORAGE  [conn1] This may be due to data corruption. Please read the documentation for starting MongoDB with --repair here: http://dochub.mongodb.org/core/repair
2019-03-27T00:16:00.224+0000 F -        [conn1] Fatal Assertion 50882 at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 143
2019-03-27T00:16:00.224+0000 F -        [conn1] 

***aborting after fassert() failure

Solution (a bit naive)

  1. In macOS
  2. As soon as mongo docker container is running, send command docker exec -i mongodb chown -R mongodb:mongodb /data to change user:group in data folder
  3. No error even after mongoose tries to connect mongodb

This solution works only in macOS, but not in ubuntu..
I'll update if I figure out what the real problem is..!😭

@wglambert
Copy link

Docker for Mac/Windows use Virtualbox to run Docker. And Vbox has a bug with shared folders, which Docker utilizes for host->container volume mounting if it's in Vbox.
The workaround is to use named volumes
MariaDB/mariadb-docker#152 (comment)

https://www.virtualbox.org/ticket/819#comment:77

@yosifkit
Copy link
Member

@wglambert is correct; even if you are using Docker for Mac (and thus xhyve instead of VirtualBox), you will still have problems that the shared file system from VM to Host does not support everything that MongoDB needs to run like fsync on directories or Raw access on open (example kubernetes/kubernetes#73412 (comment)).

note: I have no idea why your chown -R /data while the container entrypoint is starting would have any effect since I didn't think you could change the user of the mount point (/data/db) and we already chown everything on start:

mongo/4.0/docker-entrypoint.sh

Line 14 in 86974ba

find /data/configdb /data/db \! -user mongodb -exec chown mongodb '{}' +

@dev-nicelee
Copy link
Author

Like @wglambert said, using named volumes sorts out this issue.
Also, I've figured it out how it didn't work according to @yosifkit's comment!

Thanks for all your help 👍

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question Usability question, not directly related to an error with the image
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@yosifkit @wglambert @dev-nicelee