ERROR: child process failed, exited with 51

[sebastiansterk]

Running the latest docker image (image id: a440572ac3c1 / tag 6.0.4 or latest) by using docker compose the process fails with the following error:
ERROR: child process failed, exited with 51

My docker compose file

version: '3.1'

services:

  mongo:
    image: mongo:latest
    restart: always
    environment:
      MONGO_INITDB_ROOT_USERNAME: root
      MONGO_INITDB_ROOT_PASSWORD: example

Using image tag =<6.0.3 everything works fine.

[willspader]

Same problem w/ tags 6.0 and 6.0.4 here. I picked tag 5.0 randomly and it worked.

[tianon]

Any other logs you can provide that might be helpful? A more reliable reproducer? (I'm not able to reproduce myself 🙈)

[u8675309]

This is happening to us also.

It began with version 6.0.4. This seems to be when Ubuntu was switched from focal to jammy. Versions 6.03 and 6.0.4-focal both work without this issue.

It is the mongod command in docker-entrypoint.sh that is exiting with code 51. This is the output from manually running the mongod command:

# mongod --bind_ip 127.0.0.1 --port 27017 --tlsMode disabled --logpath /data/db/docker-initdb.log --logappend --pidfilepath /tmp/docker-entrypoint-temp-mongod.pid --fork
about to fork child process, waiting until server is ready for connections.
forked process: 44
ERROR: child process failed, exited with 51
To see additional information in this output, start without the "--fork" option.

Without the --fork:

# mongod --bind_ip 127.0.0.1 --port 27017 --tlsMode disabled --logpath /data/db/docker-initdb.log --logappend --pidfilepath /tmp/docker-entrypoint-temp-mongod.pid
Aborted (core dumped)

I thought it might have something to do with filesystem, but one system has xfs and another has ext4 on the partition where the volume is. They both fail.

When starting a container with 6.0.4 with a previously created and working data_db volume, there is this error instead:

"t":{"$date":"2023-02-09T02:45:00.793+00:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
{"t":{"$date":"2023-02-09T02:45:00.793+00:00"},"s":"F",  "c":"CONTROL",  "id":6384300, "ctx":"main","msg":"Writing fatal message","attr":{"message":"terminate() called. An exception is active; attempting to gather more information\n"}}
{"t":{"$date":"2023-02-09T02:45:00.793+00:00"},"s":"F",  "c":"CONTROL",  "id":6384300, "ctx":"main","msg":"Writing fatal message","attr":{"message":"std::exception::what(): Operation not permitted\nActual exception type: std::system_error\n\n"}}
{"t":{"$date":"2023-02-09T02:45:00.961+00:00"},"s":"I",  "c":"CONTROL",  "id":31380,   "ctx":"main","msg":"BACKTRACE","attr":{"bt":{"backtrace":[{"a":"560C33C408D4","b":"560C2EE62000","o":"4DDE8D4","s":"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.362","C":"mongo::stack_trace_detail::(anonymous namespace)::printStackTraceImpl(mongo::stack_trace_detail::(anonymous namespace)::Options const&, mongo::StackTraceSink*) [clone .constprop.362]","s+":"1F4"},{"a":"560C33C42E19","b":"560C2EE62000","o":"4DE0E19","s":"_ZN5mongo15printStackTraceEv","C":"mongo::printStackTrace()","s+":"29"},{"a":"560C33C3D167","b":"560C2EE62000","o":"4DDB167","s":"_ZN5mongo12_GLOBAL__N_111myTerminateEv","C":"mongo::(anonymous namespace)::myTerminate()","s+":"D7"},{"a":"560C33DC7BF6","b":"560C2EE62000","o":"4F65BF6","s":"_ZN10__cxxabiv111__terminateEPFvvE","C":"__cxxabiv1::__terminate(void (*)())","s+":"6"},{"a":"560C33DC7C31","b":"560C2EE62000","o":"4F65C31","s":"_ZSt9terminatev","C":"std::terminate()","s+":"11"},{"a":"560C33DC7D6B","b":"560C2EE62000","o":"4F65D6B","s":"__cxa_throw","s+":"4B"},{"a":"560C30D7147B","b":"560C2EE62000","o":"1F0F47B","s":"_ZSt20__throw_system_errori.cold.24","C":"std::__throw_system_error(int) [clone .cold.24]","s+":"2F"},{"a":"560C33DE3F69","b":"560C2EE62000","o":"4F81F69","s":"_ZNSt6thread15_M_start_threadESt10unique_ptrINS_6_StateESt14default_deleteIS1_EEPFvvE","C":"std::thread::_M_start_thread(std::unique_ptr<std::thread::_State, std::default_delete<std::thread::_State> >, void (*)())","s+":"29"},{"a":"560C31D0C07A","b":"560C2EE62000","o":"2EAA07A","s":"_ZN5mongo27startSignalProcessingThreadENS_13LogFileStatusE","C":"mongo::startSignalProcessingThread(mongo::LogFileStatus)","s+":"11A"},{"a":"560C30F821EA","b":"560C2EE62000","o":"21201EA","s":"_ZN5mongo11mongod_mainEiPPc","C":"mongo::mongod_main(int, char**)","s+":"B8A"},{"a":"560C30D721BE","b":"560C2EE62000","o":"1F101BE","s":"main","s+":"E"},{"a":"7FADB3D23D90","b":"7FADB3CFA000","o":"29D90","s":"__libc_init_first","s+":"90"},{"a":"7FADB3D23E40","b":"7FADB3CFA000","o":"29E40","s":"__libc_start_main","s+":"80"},{"a":"560C30F7CA95","b":"560C2EE62000","o":"211AA95","s":"_start","s+":"25"}],"processInfo":{"mongodbVersion":"6.0.4","gitVersion":"44ff59461c1353638a71e710f385a566bcd2f547","compiledModules":[],"uname":{"sysname":"Linux","release":"3.10.0-1160.2.1.el7.x86_64","version":"#1 SMP Mon Sep 21 21:00:09 EDT 2020","machine":"x86_64"},"somap":[{"b":"560C2EE62000","elfType":3,"buildId":"BCB8F6C3AD4ABF41C81882BAE25C6885C6266CC4"},{"b":"7FADB3CFA000","path":"/lib/x86_64-linux-gnu/libc.so.6","elfType":3,"buildId":"69389D485A9793DBE873F0EA2C93E02EFAA9AA3D"}]}}},"tags":[]}

[tianon]

I wonder if https://www.mongodb.com/docs/manual/administration/production-notes/#x86_64 got a bump in requirements but it wasn't documented yet? 😬

Can someone who can reproduce run strace on the process or gdb the core dump to help narrow down what's happening?

[yosifkit]

This seems to be when Ubuntu was switched from focal to jammy

🤔 This is possibly host libseccomp related like tianon/docker-brew-ubuntu-core#236 and docker-library/tomcat#269 (comment). Can someone who can reproduce try running with --security-opt seccomp=unconfined and see if it works?

[u8675309]

Can someone who can reproduce run strace on the process

[pid    93] write(6, "{\"t\":{\"$date\":\"2023-02-09T22:20:24.297+00:00\"},\"s\":\"I\",  \"c\":\"RE"..., 235) = 235
[pid    93] prlimit64(0, RLIMIT_NOFILE, NULL, {rlim_cur=1024*1024, rlim_max=1024*1024}) = 0
[pid    93] newfstatat(AT_FDCWD, "/tmp", {st_mode=S_IFDIR|S_ISVTX|0777, st_size=55, ...}, 0) = 0                     
[pid    93] openat(AT_FDCWD, "/tmp/docker-entrypoint-temp-mongod.pid", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 8
[pid    93] getpid()                    = 93
[pid    93] write(8, "93\n", 3)         = 3
[pid    93] newfstatat(AT_FDCWD, "/tmp/docker-entrypoint-temp-mongod.pid", {st_mode=S_IFREG|0644, st_size=3, ...}, 0) = 0
[pid    93] chmod("/tmp/docker-entrypoint-temp-mongod.pid", 0644) = 0
[pid    93] close(8)                    = 0 
[pid    93] write(6, "{\"t\":{\"$date\":\"2023-02-09T22:20:24.297+00:00\"},\"s\":\"I\",  \"c\":\"CO"..., 137) = 137  
[pid    93] rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 TERM XCPU], NULL, 8) = 0
[pid    93] brk(0x55591eddb000)         = 0x55591eddb000
[pid    93] rt_sigaction(SIGRT_1, {sa_handler=0x7f83d62148f0, sa_mask=[], sa_flags=SA_RESTORER|SA_ONSTACK|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f83d61c5520}, NULL, 8) = 0
[pid    93] rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
[pid    93] mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f83d4f73000
[pid    93] mprotect(0x7f83d4f74000, 8388608, PROT_READ|PROT_WRITE) = 0                                              
[pid    93] rt_sigprocmask(SIG_BLOCK, ~[], [HUP INT USR1 TERM XCPU], 8) = 0
[pid    93] clone3({flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, child_tid=0x7f83d5773910, parent_tid=0x7f83d5773910, exit_signal=0, stack=0x7f83d4f73000, stack_size=0x7ff980, tls=0x7f83d5773640}, 88) = -1 EPERM (Operation not permitted)
[pid    93] rt_sigprocmask(SIG_SETMASK, [HUP INT USR1 TERM XCPU], NULL, 8) = 0                                       
[pid    93] futex(0x7f83d63ca210, FUTEX_WAKE_PRIVATE, 2147483647) = 0
[pid    93] write(6, "{\"t\":{\"$date\":\"2023-02-09T22:20:24.298+00:00\"},\"s\":\"F\",  \"c\":\"CO"..., 236) = 236
[pid    93] write(6, "{\"t\":{\"$date\":\"2023-02-09T22:20:24.298+00:00\"},\"s\":\"F\",  \"c\":\"CO"..., 246) = 246

The 22:20:24.297 message is "Multi threading initialized". Then the .298 messages are the "Writing fatal message" ones.

[u8675309]

Confirmed that the issue does not happen with docker option --security-opt seccomp=unconfined.

It also does not happen with

Docker version 20.10.21, build baeda1f
libseccomp-2.3.1-4.el7.x86_64

but does happen with

Docker version 19.03.8, build afacb8b
libseccomp-2.3.1-4.el7.x86_64

[yosifkit]

Confirmed that the issue does not happen with docker option --security-opt seccomp=unconfined.

clone3({flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, ...}, 88) = -1 EPERM (Operation not permitted)

Thanks for confirming. clone3 is a newer syscall used in Ubuntu Jammy and the seccomp profile used by docker defaults to blocking syscalls that it doesn't know about (the eperm). Please update docker and libseccomp on the host in order to run jammy based images (tianon/docker-brew-ubuntu-core#236)

This is similar to the issue in Alpine 3.14 images when they started using a new syscall:

• Alpine 3.14 make: /bin/sh: Operation not permitted php#1177
• Alpine 3.14 images can fail on Docker versions older than 20.10 ruby#351
• https://wiki.alpinelinux.org/wiki/Release_Notes_for_Alpine_3.14.0#faccessat2

[lindelius]

Same issue when running containers on CircleCI... Switching to mongo:6.0-focal fixed it 👍

[patrickacioli]

Same problem here and as @lindelius comment, switching to mongo:6.0-focal fixed it.

[tianon]

The "correct" solution is to update Docker, runc, and libseccomp on your host, but downgrading is a fine temporary solution (I wouldn't recommend it long term or for production workloads since we aren't actively maintaining that focal image anymore).