WiredTiger error .. "error":95" .. fallocate:: Operation not supported

MongoDB Percona Server for MongoDB
1

Hi, I’m just experimenting with MongoDB.

I get the following errors when I start a container with the database.

psmdb_1 | {"t":{"$date":"2020-09-01T19:50:00.963+00:00"},"s":"E", "c":"STORAGE", "id":22435,  "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1598989800:963675][1:0x7f882be42700], log-server: __posix_std_fallocate, 58: /data/db/journal/WiredTigerTmplog.0000000003: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-01T19:50:00.963+00:00"},"s":"E", "c":"STORAGE", "id":22435,  "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1598989800:963758][1:0x7f882be42700], log-server: __posix_sys_fallocate, 75: /data/db/journal/WiredTigerTmplog.0000000003: fallocate:: Operation not supported"}}

I run Percona Server for MongoDB in Docker using docker-compose

version: "3"
services:
 psmdb:
  image: "percona/percona-server-mongodb:4.4"
  volumes:
   - ./data:/data/db
  restart: always
  environment:
   MONGO_INITDB_ROOT_USERNAME: root
   MONGO_INITDB_ROOT_PASSWORD: secret
   MONGO_INITDB_DATABASE: forum
  ports: 
   - "27017:27017"


I recently upgraded from 4.2 to 4.4 . Perhaps the problem appeared after I changed the container from MongoDB with version 4.2 to version 4.4.

I used the instruction from here. https://www.percona.com/doc/percona-server-for-mongodb/4.4/install/upgrade_from_42.html#upgrading-on-debian-or-ubuntu

It seems that nothing had to be done for Upgrade 4.2 to 4.4.

My application works fine. I guess I shouldn’t fix the error, just wondering.

2

Hi Bazhenov-san.

fallocate is a standard unix/posix syscall, so I sense there is a limitation of the docker container compared to a normal server. I quickly found a stackoverflow QA page that mentions that docker uses a (pseudo) filesystem https://stackoverflow.com/questions/31155591/fallocate-failing-inside-my-docker-container . I don’t know if this is still true of docker these days though.

I’ve checked to see if version 4.4 MongoDB has started using fallocate for the first time, but this is not the case: Present in v4.2 https://github.com/mongodb/mongo/blob/v4.2/src/third_party/wiredtiger/src/os_posix/os_fallocate.c code.

There have been changes in the way WiredTiger does disk IO in v4.4 though: https://engineering.mongodb.com/post/getting-storage-engines-ready-for-fast-storage-devices

3

I’m having a bit of trouble using this comment form - whenever I take focus off the cursor the javascript of the page goes into 10 ~ 30 sec CPU thrashing and Chrome suggests killing the page.

4

Anyhow I don’t think the errors are harmless - the s(everity) “E” field shows that this log message is for an error, not informational. So I’ll ask our Cloud team if they know if there is a limitation against fallocate in docker.

5

Hi, @Akira_Kurogane ,

I’m having a bit of trouble using this comment form - whenever I take focus off the cursor the javascript of the page goes into 10 ~ 30 sec CPU thrashing and Chrome suggests killing the page.I’m having a bit of trouble using this comment form - whenever I take focus off the cursor the javascript of the page goes into 10 ~ 30 sec CPU thrashing and Chrome suggests killing the page.

Thank you for informing me. I will try to change the editor and investigate the problem.

6

Just in case, I attach a little more logs. The error is repeated three times when I start the container.

psmdb_1  | {"t":{"$date":"2020-09-07T21:06:12.669+00:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:12.698+00:00"},"s":"I", "c":"STORAGE", "id":22315, "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=483M,session_max=33000,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,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:13.252+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512773:252194][1:0x7f637871cbc0], connection: __posix_std_fallocate, 58: /data/db/journal/WiredTigerTmplog.0000000001: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:13.252+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"initandlisten","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512773:252292][1:0x7f637871cbc0], connection: __posix_sys_fallocate, 75: /data/db/journal/WiredTigerTmplog.0000000001: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:19.824+00:00"},"s":"I", "c":"STORAGE", "id":22430, "ctx":"initandlisten","msg":"WiredTiger message","attr":{"message":"[1599512779:824700][1:0x7f637871cbc0], txn-recover: [WT_VERB_RECOVERY_PROGRESS] Recovering log 39 through 40"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:20.659+00:00"},"s":"I", "c":"RECOVERY", "id":23987, "ctx":"initandlisten","msg":"WiredTiger recoveryTimestamp","attr":{"recoveryTimestamp":{"$timestamp":{"t":0,"i":0}}}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:20.662+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512780:662016][1:0x7f636fa4a700], log-server: __posix_std_fallocate, 58: /data/db/journal/WiredTigerTmplog.0000000002: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:20.662+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512780:662107][1:0x7f636fa4a700], log-server: __posix_sys_fallocate, 75: /data/db/journal/WiredTigerTmplog.0000000002: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:20.680+00:00"},"s":"I", "c":"STORAGE", "id":22262, "ctx":"initandlisten","msg":"Timestamp monitor starting"}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:20.757+00:00"},"s":"I", "c":"NETWORK", "id":23016, "ctx":"listener","msg":"Waiting for connections","attr":{"port":27017,"ssl":"off"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:27.921+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512787:920986][1:0x7f636fa4a700], log-server: __posix_std_fallocate, 58: /data/db/journal/WiredTigerTmplog.0000000003: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:27.921+00:00"},"s":"E", "c":"STORAGE", "id":22435, "ctx":"thread1","msg":"WiredTiger error","attr":{"error":95,"message":"[1599512787:921073][1:0x7f636fa4a700], log-server: __posix_sys_fallocate, 75: /data/db/journal/WiredTigerTmplog.0000000003: fallocate:: Operation not supported"}}
psmdb_1 | {"t":{"$date":"2020-09-07T21:06:28.467+00:00"},"s":"I", "c":"NETWORK", "id":22943, "ctx":"listener","msg":"connection accepted","attr":{"remote":"172.19.0.1:46658","sessionId":1,"connectionCount":1}}

7

Hi I am experiencing the same issue. trying to setup a mongo replica set on AKS. This I think leads to another issue further down the line that causes the container to not startup at all as it is unable to recover from a journal file, as the Wired tiger engine cannot access the file anymore

Has this been Resolved?

8

Hi Stef.

As I recall I did ask for help with the Cloud team (which does kubernetes) but that was a while ago and no response as I recall. I don’t know at the moment.

The error is not with MongoDB - it has used a unix filesystem syscall that should be working when filesystem space is available, but doesn’t in docker apparently. At least we’ve never observed it fail anywhere else and there is a good hint that this is a limitation of UnionFS used by docket.

I’m going to ask the question in the Kubernetes Operator for PSMDB forum. https://forums.percona.com/discussion/56348/does-docker-use-unionfs-and-does-it-cause-fallocate-operation-not-supported . Hopefully we can identify the bug and make this a JIRA ticket with a clear goal soon.

9

@daniil.bazhenov could you please show your docker info?

What filesystem do you use for your data dir?

10

Hi @Stef - if you still experience the “error”:95" “fallocate:: Operation not supported” system could you please share the output of docker info in the environment it happens. (Related discussion is in https://forums.percona.com/discussion/56348/does-docker-use-unionfs-and-does-it-cause-fallocate-operation-not-supported ).@Stef