Mongo 3.0 now failing at start as of 2 days ago

[ernestm]

Since the new rev of mongo:3.0 with Dockerfile and entrypoint change a couple days ago, our mongo containers have started failing with a log message about "parent exiting":

(normal startup stuff)
2017-03-22T13:59:32.814+0000 I CONTROL [initandlisten]
child process started successfully, parent exiting
2017-03-22T13:59:32.815+0000 I INDEX [initandlisten] allocating new ns file /data/db/local.ns, filling with zeroes...

The "child process started successfully, parent exiting" line is new; old logs from when it worked are identical except for that line (and of course subsequent lines from the container staying up). If the entrypoint process is really going away I can understand why the container dies, of course.

We're running it pretty much vanilla, e.g.

mongo:
image: mongo:3.0
container_name: otx_mongo
volumes:
- ./data/mongo:/data/db
ports:
- 27017:27017

Is this something I can work around on my end?

Thanks,
Ernest

[ernestm]

I believe it is due to the introduction of processManagement: { fork: true } as a default -

Previous version of container:

2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=bb25ed9f7f19
2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] db version v3.0.12
2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] git version: 33934938e0e95d534cebbaff656cde916b9c3573
2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] build info: Linux ip-10-167-97-24 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] allocator: tcmalloc
2017-03-22T15:26:52.208+0000 I CONTROL [initandlisten] options: {}

New version of container (terminates):

2017-03-22T15:26:09.459+0000 I CONTROL [initandlisten] MongoDB starting : pid=18 port=27017 dbpath=/data/db 64-bit host=439a99b6d0a3
2017-03-22T15:26:09.460+0000 I CONTROL [initandlisten] db version v3.0.14
2017-03-22T15:26:09.460+0000 I CONTROL [initandlisten] git version: 08352afcca24bfc145240a0fac9d28b978ab77f3
2017-03-22T15:26:09.460+0000 I CONTROL [initandlisten] build info: Linux ip-10-30-223-232 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2017-03-22T15:26:09.460+0000 I CONTROL [initandlisten] allocator: tcmalloc
2017-03-22T15:26:09.460+0000 I CONTROL [initandlisten] options: { net: { bindIp: "127.0.0.1" }, processManagement: { fork: true }, systemLog: { destination: "file", path: "/proc/1/fd/1" } }

[yosifkit]

Since these are uninitialized containers, then it is by design:

mongo/3.0/docker-entrypoint.sh

Lines 70 to 125 in 23b4483

	if [ -z "$definitelyAlreadyInitialized" ]; then
	"$@" --fork --bind_ip 127.0.0.1 --logpath "/proc/$$/fd/1"
	mongo=( mongo --quiet )
	# check to see that "mongod" actually did start up (catches "--help", "--version", MongoDB 3.2 being silly, etc)
	if ! "${mongo[@]}" 'admin' --eval 'quit(0)' &> /dev/null; then
	echo >&2
	echo >&2 'error: mongod does not appear to have started up -- perhaps it had an error?'
	echo >&2
	exit 1
	fi
	if [ "$MONGO_INITDB_ROOT_USERNAME" ] && [ "$MONGO_INITDB_ROOT_PASSWORD" ]; then
	rootAuthDatabase='admin'
	"${mongo[@]}" "$rootAuthDatabase" <<-EOJS
	db.createUser({
	user: $(jq --arg 'user' "$MONGO_INITDB_ROOT_USERNAME" --null-input '$user'),
	pwd: $(jq --arg 'pwd' "$MONGO_INITDB_ROOT_PASSWORD" --null-input '$pwd'),
	roles: [ { role: 'root', db: $(jq --arg 'db' "$rootAuthDatabase" --null-input '$db') } ]
	})
	EOJS
	mongo+=(
	--username="$MONGO_INITDB_ROOT_USERNAME"
	--password="$MONGO_INITDB_ROOT_PASSWORD"
	--authenticationDatabase="$rootAuthDatabase"
	)
	fi
	export MONGO_INITDB_DATABASE="${MONGO_INITDB_DATABASE:-test}"
	echo
	for f in /docker-entrypoint-initdb.d/*; do
	case "$f" in
	*.sh) echo "$0: running $f"; . "$f" ;;
	*.js) echo "$0: running $f"; "${mongo[@]}" "$MONGO_INITDB_DATABASE" "$f"; echo ;;
	*) echo "$0: ignoring $f" ;;
	esac
	echo
	done
	"$@" --shutdown
	echo
	echo 'MongoDB init process complete; ready for start up.'
	echo
	fi
	unset MONGO_INITDB_ROOT_USERNAME
	unset MONGO_INITDB_ROOT_PASSWORD
	unset MONGO_INITDB_DATABASE
	fi
	exec "$@"

. We start mongod in the background listening only on localhost (the bindIp: "127.0.0.1" seen in your logs), process user setup, and scripts from /docker-entrypoint-initdb.d/ and then stop mongod and let it start naturally as the main process of the container (exec "$@" at the end of the script).

Does the container actually stop? Is there an error we fail to account for?

[ernestm]

The container actually stops. Backing off to mongo:3.0.12 it works.

3.0.14:

EMUELLER-MBP-AUS:labs-pulse ernestmueller$ docker run -d -p 27017:27017 -v $PWD/data/mongo:/data/db --name otx_mongo mongo:3.0
a8bda571a8fc1121ade1c159dfa5a40c4baf1eaab7592c537fe8950a2f64f51f
EMUELLER-MBP-AUS:labs-pulse ernestmueller$ docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
a8bda571a8fc mongo:3.0 "docker-entrypoint..." 3 seconds ago Exited (1) 1 second ago otx_mongo
EMUELLER-MBP-AUS:labs-pulse ernestmueller$ docker logs otx_mongo
about to fork child process, waiting until server is ready for connections.
forked process: 18
2017-03-22T19:01:23.490+0000 I CONTROL [initandlisten] MongoDB starting : pid=18 port=27017 dbpath=/data/db 64-bit host=a8bda571a8fc
2017-03-22T19:01:23.491+0000 I CONTROL [initandlisten] db version v3.0.14
2017-03-22T19:01:23.491+0000 I CONTROL [initandlisten] git version: 08352afcca24bfc145240a0fac9d28b978ab77f3
2017-03-22T19:01:23.491+0000 I CONTROL [initandlisten] build info: Linux ip-10-30-223-232 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2017-03-22T19:01:23.491+0000 I CONTROL [initandlisten] allocator: tcmalloc
2017-03-22T19:01:23.491+0000 I CONTROL [initandlisten] options: { net: { bindIp: "127.0.0.1" }, processManagement: { fork: true }, systemLog: { destination: "file", path: "/proc/1/fd/1" } }
2017-03-22T19:01:23.509+0000 I JOURNAL [initandlisten] journal dir=/data/db/journal
2017-03-22T19:01:23.511+0000 I JOURNAL [initandlisten] recover : no journal files present, no recovery needed
2017-03-22T19:01:23.560+0000 I JOURNAL [durability] Durability thread started
2017-03-22T19:01:23.561+0000 I JOURNAL [journal writer] Journal writer thread started
child process started successfully, parent exiting
2017-03-22T19:01:23.570+0000 I INDEX [initandlisten] allocating new ns file /data/db/local.ns, filling with zeroes...

error: mongod does not appear to have started up -- perhaps it had an error?`

I think it has to do with the creation of the items in the data directory; when I run 3.0.12 this is the full output:

EMUELLER-MBP-AUS:labs-pulse ernestmueller$ docker logs otx_mongo
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] MongoDB starting : pid=1 port=27017 dbpath=/data/db 64-bit host=e5f6ab3125e1
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] db version v3.0.12
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] git version: 33934938e0e95d534cebbaff656cde916b9c3573
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] build info: Linux ip-10-167-97-24 3.2.0-4-amd64 #1 SMP Debian 3.2.46-1 x86_64 BOOST_LIB_VERSION=1_49
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] allocator: tcmalloc
2017-03-22T19:03:23.412+0000 I CONTROL [initandlisten] options: {}
2017-03-22T19:03:23.434+0000 I JOURNAL [initandlisten] journal dir=/data/db/journal
2017-03-22T19:03:23.436+0000 I JOURNAL [initandlisten] recover : no journal files present, no recovery needed
2017-03-22T19:03:23.483+0000 I JOURNAL [durability] Durability thread started
2017-03-22T19:03:23.484+0000 I JOURNAL [journal writer] Journal writer thread started
2017-03-22T19:03:23.496+0000 I INDEX [initandlisten] allocating new ns file /data/db/local.ns, filling with zeroes...
2017-03-22T19:03:23.623+0000 I STORAGE [FileAllocator] allocating new datafile /data/db/local.0, filling with zeroes...
2017-03-22T19:03:23.626+0000 I STORAGE [FileAllocator] creating directory /data/db/_tmp
2017-03-22T19:03:23.741+0000 I STORAGE [FileAllocator] done allocating datafile /data/db/local.0, size: 64MB, took 0.112 secs
2017-03-22T19:03:23.823+0000 I NETWORK [initandlisten] waiting for connections on port 27017

If I then stop that and run v3.0.14 on top of that same data/mongo directory it starts up. So perhaps something about creating the nsfile, datafile, and/or tempdir from scratch isn't working right in the newer entrypoint.

[tianon]

Huh, this is sounding/looking similar to the issue I could only reproduce on 3.2:

mongo/3.2/docker-entrypoint.sh

Lines 76 to 80 in 23b4483

	if ! "${mongo[@]}" 'admin' --eval 'quit(0)' &> /dev/null; then
	# TODO figure out why only MongoDB 3.2 seems to exit from "--fork" before it's actually listening
	# (adding "sleep 0.01" was sufficient on Tianon's local box, hence this tiny "retry up to one time")
	sleep 5
	fi

if ! "${mongo[@]}" 'admin' --eval 'quit(0)' &> /dev/null; then
	# TODO figure out why only MongoDB 3.2 seems to exit from "--fork" before it's actually listening
	# (adding "sleep 0.01" was sufficient on Tianon's local box, hence this tiny "retry up to one time")
	sleep 5
fi

[yosifkit]

@tianon what if we do a retry loop on all of the mongo versions like mysql and use pidof mongod to ensure that it didn't just die (ie --version or bad config) and then check if we can access?

[ernestm]

Fixed it for me, thanks!