Error saving history file: FileOpenFailed: Unable to open() file /home/mongodb/.dbshell: Unknown error

[leon0707]

Dockerfile

FROM mongo
ADD ./mongo-init.sh /docker-entrypoint-initdb.d/

mongodb_1  | about to fork child process, waiting until server is ready for connections.
mongodb_1  | forked process: 29
mongodb_1  | 2019-01-15T21:20:47.367+0000 I CONTROL  [main] ***** SERVER RESTARTED *****
mongodb_1  | 2019-01-15T21:20:47.370+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] MongoDB starting : pid=29 port=27017 dbpath=/data/db 64-bit host=343629fa23cd
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] db version v4.0.5
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] git version: 3739429dd92b92d1b0ab120911a23d50bf03c412
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] allocator: tcmalloc
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] modules: none
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] build environment:
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten]     distarch: x86_64
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten]     target_arch: x86_64
mongodb_1  | 2019-01-15T21:20:47.374+0000 I CONTROL  [initandlisten] options: { net: { bindIp: "127.0.0.1", port: 27017, ssl: { mode: "disabled" } }, processManagement: { fork: true, pidFilePath: "/tmp/docker-entrypoint-temp-mongod.pid" }, systemLog: { destination: "file", logAppend: true, path: "/proc/1/fd/1" } }
mongodb_1  | 2019-01-15T21:20:47.374+0000 I STORAGE  [initandlisten]
mongodb_1  | 2019-01-15T21:20:47.374+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
mongodb_1  | 2019-01-15T21:20:47.374+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
mongodb_1  | 2019-01-15T21:20:47.375+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=487M,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),
mongodb_1  | 2019-01-15T21:20:47.866+0000 I STORAGE  [initandlisten] WiredTiger message [1547587247:866155][29:0x7eff7bb21a40], txn-recover: Set global recovery timestamp: 0
mongodb_1  | 2019-01-15T21:20:47.873+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
mongodb_1  | 2019-01-15T21:20:47.883+0000 I CONTROL  [initandlisten]
mongodb_1  | 2019-01-15T21:20:47.883+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
mongodb_1  | 2019-01-15T21:20:47.883+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
mongodb_1  | 2019-01-15T21:20:47.883+0000 I CONTROL  [initandlisten]
mongodb_1  | 2019-01-15T21:20:47.883+0000 I STORAGE  [initandlisten] createCollection: admin.system.version with provided UUID: 6019a1c5-fc8c-45ed-9355-5677a9ed6c47
mongodb_1  | 2019-01-15T21:20:47.892+0000 I COMMAND  [initandlisten] setting featureCompatibilityVersion to 4.0
mongodb_1  | 2019-01-15T21:20:47.897+0000 I STORAGE  [initandlisten] createCollection: local.startup_log with generated UUID: bc5c6df0-c572-4cbe-815c-daebc8c7f596
mongodb_1  | 2019-01-15T21:20:47.909+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'
mongodb_1  | 2019-01-15T21:20:47.911+0000 I NETWORK  [initandlisten] waiting for connections on port 27017
mongodb_1  | 2019-01-15T21:20:47.911+0000 I STORAGE  [LogicalSessionCacheRefresh] createCollection: config.system.sessions with generated UUID: b7cba875-b5b1-4633-9d4e-944a52b3c84a
mongodb_1  | child process started successfully, parent exiting
mongodb_1  | 2019-01-15T21:20:47.925+0000 I INDEX    [LogicalSessionCacheRefresh] build index on: config.system.sessions properties: { v: 2, key: { lastUse: 1 }, name: "lsidTTLIndex", ns: "config.system.sessions", expireAfterSeconds: 1800 }
mongodb_1  | 2019-01-15T21:20:47.925+0000 I INDEX    [LogicalSessionCacheRefresh] 	 building index using bulk method; build may temporarily use up to 500 megabytes of RAM
mongodb_1  | 2019-01-15T21:20:47.926+0000 I INDEX    [LogicalSessionCacheRefresh] build index done.  scanned 0 total records. 0 secs
mongodb_1  | 2019-01-15T21:20:47.969+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36626 #1 (1 connection now open)
mongodb_1  | 2019-01-15T21:20:47.969+0000 I NETWORK  [conn1] received client metadata from 127.0.0.1:36626 conn1: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.0.5" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
mongodb_1  | 2019-01-15T21:20:47.972+0000 I NETWORK  [conn1] end connection 127.0.0.1:36626 (0 connections now open)
mongodb_1  | 2019-01-15T21:20:48.032+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:36628 #2 (1 connection now open)
mongodb_1  | 2019-01-15T21:20:48.032+0000 I NETWORK  [conn2] received client metadata from 127.0.0.1:36628 conn2: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "4.0.5" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
mongodb_1  | 2019-01-15T21:20:48.065+0000 I STORAGE  [conn2] createCollection: admin.system.users with generated UUID: 0ec16545-de93-480f-ad22-184f838e30b6
mongodb_1  | Successfully added user: {
mongodb_1  | 	"user" : "root",
mongodb_1  | 	"roles" : [
mongodb_1  | 		{
mongodb_1  | 			"role" : "root",
mongodb_1  | 			"db" : "admin"
mongodb_1  | 		}
mongodb_1  | 	]
mongodb_1  | }
mongodb_1  | 2019-01-15T21:20:48.084+0000 E -        [main] Error saving history file: FileOpenFailed: Unable to open() file /home/mongodb/.dbshell: Unknown error

[wglambert]

Looks like a bug that was fixed in 3.5.10, and you're encountering it on 4.0.5
https://jira.mongodb.org/browse/SERVER-26871
https://jira.mongodb.org/browse/SERVER-32473

Starting a mongo:4.0.5 container doesn't show any errors for me

$ docker run -d --rm --name mongo mongo:4.0.5
d7b0f2308d4be6acdb874a0b11dd2abb96608857e296b3397209963bd70f7388

$ docker logs mongo
2019-01-16T17:53:09.971+0000 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'                 
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=d7b0f2308d4b                          
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] db version v4.0.5                                                                                     
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] git version: 3739429dd92b92d1b0ab120911a23d50bf03c412                                                 
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016                                                           
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] allocator: tcmalloc                                                                                   
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] modules: none                                                                                         
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] build environment:                                                                                    
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604                                                                               
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten]     distarch: x86_64                                                                                  
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten]     target_arch: x86_64                                                                               
2019-01-16T17:53:09.973+0000 I CONTROL  [initandlisten] options: { net: { bindIpAll: true } }                                                                 
2019-01-16T17:53:09.973+0000 I STORAGE  [initandlisten]                                                                                                       
2019-01-16T17:53:09.973+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine       
2019-01-16T17:53:09.973+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem                                   
2019-01-16T17:53:09.973+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=979M,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-01-16T17:53:10.598+0000 I STORAGE  [initandlisten] WiredTiger message [1547661190:598541][1:0x7f40fc54da40], txn-recover: Set global recovery timestamp: 0                                                                                                                                                             
2019-01-16T17:53:10.721+0000 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)                                                     
2019-01-16T17:53:10.799+0000 I CONTROL  [initandlisten]                                                                                                       
2019-01-16T17:53:10.799+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.                                           
2019-01-16T17:53:10.799+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.                          
2019-01-16T17:53:10.799+0000 I CONTROL  [initandlisten]                                                                                                       
2019-01-16T17:53:10.800+0000 I STORAGE  [initandlisten] createCollection: admin.system.version with provided UUID: 52806025-e5ad-4578-8216-1de9d92f2248       
2019-01-16T17:53:10.904+0000 I COMMAND  [initandlisten] setting featureCompatibilityVersion to 4.0                                                            
2019-01-16T17:53:10.914+0000 I STORAGE  [initandlisten] createCollection: local.startup_log with generated UUID: beb27e97-eee9-44ac-86f0-379cce977e11         
2019-01-16T17:53:10.955+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/data/db/diagnostic.data'              
2019-01-16T17:53:10.958+0000 I NETWORK  [initandlisten] waiting for connections on port 27017                                                                 
2019-01-16T17:53:10.959+0000 I STORAGE  [LogicalSessionCacheRefresh] createCollection: config.system.sessions with generated UUID: 34c27039-408e-4147-98b0-1cf7487db169                                                                                                                                                     
2019-01-16T17:53:11.030+0000 I INDEX    [LogicalSessionCacheRefresh] build index on: config.system.sessions properties: { v: 2, key: { lastUse: 1 }, name: "lsidTTLIndex", ns: "config.system.sessions", expireAfterSeconds: 1800 }                                                                                         
2019-01-16T17:53:11.030+0000 I INDEX    [LogicalSessionCacheRefresh]     building index using bulk method; build may temporarily use up to 500 megabytes of RAM                                                                                                                                                             
2019-01-16T17:53:11.034+0000 I INDEX    [LogicalSessionCacheRefresh] build index done.  scanned 0 total records. 0 secs

[leon0707]

@wglambert I create two secrets for the mongo container MONGO_INITDB_ROOT_USERNAME, MONGO_INITDB_ROOT_PASSWORD. The container automatically creates the root user. The error message showed up between adding the root user and execution of the custom init script.

[wglambert]

So the error is shown here when mongo does something like create a user and then wants to write its history to an invalid path.

[tianon]

Ouch, looks like https://jira.mongodb.org/browse/SERVER-29103 is related -- ideally we'd want to disable the "history file" for these commands, but there's not actually a way to do that without making the history file completely unusable by default. 😞

[prokhorovn]

Dealing with exactly the same error. Mongo image v 4.0.6. First "clean" initial run on container with variables MONGO_INITDB_ROOT_USERNAME, MONGO_INITDB_ROOT_USERNAME successfully creates admin user. But after stopping container and starting it again error comes up:

2019-03-19T08:21:18.911+0000 E QUERY    [js] Error: couldn't add user: command createUser requires authentication :
_getErrorWithCode@src/mongo/shell/utils.js:25:13
DB.prototype.createUser@src/mongo/shell/db.js:1491:15
@(shell):1:1
2019-03-19T08:21:18.912+0000 E -        [main] Error saving history file: FileOpenFailed: Unable to open() file /home/mongodb/.dbshell: Unknown error

Manually hacking the container and removing env. varibles MONGO_INITDB_ROOT_USERNAME, MONGO_INITDB_ROOT_USERNAME from it resolves the issue.
So, it seems, like mongo image tries to create user from MONGO_INITDB_ROOT_USERNAME even if DB was already initialized. This is very confusing, especially considering the docs on dockerhub which say:

Do note that none of the variables below will have any effect if you start the container with a data directory that already contains a database: any pre-existing database will always be left untouched on container startup.

How to set up first super user in a proper way, so that not to break cluster after stop?

UPD: issue happens when running mongod as configsvr instance;

[lu911]

+1

[grammy-jiang]

Hi, all,

I have met this problem today. I used the docker image tag: 4.0.9.

Problem

I used docker exec -it container-mongo /bin/bash to go inside, and find:

There is no home folder for the user of mongodb.

Yes, in the error message:

2019-03-19T08:21:18.912+0000 E - [main] Error saving history file: FileOpenFailed: Unable to open() file /home/mongodb/.dbshell: Unknown error

The folder /home/mongodb does not exist.

Solution

Then my solution is:

1. Create a folder manually on your host, which will be mounted as a volume
2. Assign mongodb as the owner for this folder
3. Mount this folder in the docker-compose.yml as the home folder \home\mongodb

Remind: don't use user and group name in your host for the owner assign - instead use the id of user and group.

You can get mongodb user and group id used in the docker image:

root@4778d894024d:/# id mongodb
uid=999(mongodb) gid=999(mongodb) groups=999(mongodb)

After these steps, the error message is gone, and .dbshell shows up in the folder which owner is 999:999.

One line command:

mkdir mongo-home && \
sudo chown `docker run --rm mongo:latest id -u mongodb`:`docker run --rm mongo:latest id -g mongodb` mongo-home

Why

I check the dockerfile, and find the creation of the user mongodb is missing -m arugment:

root@4778d894024d:/# docker run --rm mongo useradd --help
Usage: useradd [options] LOGIN
useradd -D
useradd -D [options]

Options:
...
-m, --create-home create the user's home directory
...

[sadokmtir]

+1

[guillaumelachaud]

Is everybody using the manual folder workaround ? Should we proceed with a PR to add the -m option to the dockerfile ?

[tianon]

From what I've seen, the error doesn't prevent anything from working, so it's really more of a warning -- is someone else seeing behavior different from that?