0

Whenever I delete a file on my gcsfuse mounted file system, the DeleteObject command is always followed by an UpdateObject command, which fails, because the file does not exist anymore. The delete itself succeeds, both locally and on the bucket, so the delete behaves as expected, but I would like to understand why the UpdateObject command is sent and if this is just expected behaviour or perhaps points to a configuration issue on my side. Here are some setup details and a log extract (Sensitive info redacted with '#' characters):

gcsfuse version: 0.40.0

Mounting command: /usr/bin/gcsfuse --foreground --debug_fuse --debug_fs --debug_gcs --debug_http --debug_mutex --debug_invariants --log-file /home/###/gcsfuse.log ### /home/###/###

Delete Command: rm deltest.txt

Log extract:

  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "fuse_debug: Op 0x000037c6        connection.go:416] <- Unlink (parent 26, name \"deltest.txt\", PID 1193)\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 564194468
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "gcs: Req             0x44: <- DeleteObject(\"deltest.txt\")\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 564300578
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ========== REQUEST:\nDELETE http://www.googleapis.com:443/storage/v1/b/###/o/deltest.txt HTTP/1.1\r\nHost: www.googleapis.com:443\r\nUser-Agent: gcsfuse/0.40.0 (Go version go1.17.6) \r\nAuthorization: Bearer ###\r\nAccept-Encoding: gzip\r\n\r\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 564477178
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ========== RESPONSE:\nHTTP/2.0 204 No Content\r\nCache-Control: no-cache, no-store, max-age=0, must-revalidate\r\nContent-Type: application/json\r\nDate: Fri, 08 Apr 2022 08:59:05 GMT\r\nExpires: Mon, 01 Jan 1990 00:00:00 GMT\r\nPragma: no-cache\r\nServer: UploadServer\r\nVary: Origin\r\nVary: X-Origin\r\nX-Guploader-Uploadid: ###\r\n\r\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599754186
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ====================\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599813546
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "gcs: Req             0x44: -> DeleteObject(\"deltest.txt\") (35.528748ms): OK\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599832746
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "debug_fs: Unlink(26, \"deltest.txt\"): <nil>\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599883646
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "fuse_debug: Op 0x000037c6        connection.go:498] -> OK ()\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599908336
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "fuse_debug: Op 0x000037c8        connection.go:416] <- SetInodeAttributes (inode 35, PID 1193, mtime 2022-04-08 08:58:51.943138607 +0000 UTC)\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 599978196
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "gcs: Req             0x45: <- UpdateObject(\"deltest.txt\")\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 600124196
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ========== REQUEST:\nPATCH http://www.googleapis.com:443/storage/v1/b/###/o/deltest.txt?generation=###&ifMetagenerationMatch=1&projection=full HTTP/1.1\r\nHost: www.googleapis.com:443\r\nUser-Agent: gcsfuse/0.40.0 (Go version go1.17.6) \r\nContent-Length: 64\r\nAuthorization: Bearer ###\r\nContent-Type: application/json\r\nAccept-Encoding: gzip\r\n\r\n{\"metadata\":{\"gcsfuse_mtime\":\"2022-04-08T08:58:51.943138607Z\"}}\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 600343366
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ========== RESPONSE:\nHTTP/2.0 404 Not Found\r\nContent-Length: 383\r\nCache-Control: no-cache, no-store, max-age=0, must-revalidate\r\nContent-Type: application/json; charset=UTF-8\r\nDate: Fri, 08 Apr 2022 08:59:05 GMT\r\nExpires: Mon, 01 Jan 1990 00:00:00 GMT\r\nPragma: no-cache\r\nServer: UploadServer\r\nVary: Origin\r\nVary: X-Origin\r\nX-Guploader-Uploadid: ###\r\n\r\n{\n  \"error\": {\n    \"code\": 404,\n    \"message\": \"No such object:###/deltest.txt\",\n    \"errors\": [\n      {\n        \"message\": \"No such object: ###/deltest.txt\",\n        \"domain\": \"global\",\n        \"reason\": \"notFound\"\n      }\n    ]\n  }\n}\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618031945
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "http: ====================\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618071915
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "gcs: Req             0x45: -> UpdateObject(\"deltest.txt\") (18.039079ms): not retrying UpdateObject(\"deltest.txt\"): gcs.NotFoundError: googleapi: Error 404: No such object: ###/deltest.txt, notFound\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618163665
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "debug_fs: SetInodeAttributes(35): SetMtime: UpdateObject: not retrying UpdateObject(\"###/deltest.txt\"): gcs.NotFoundError: googleapi: Error 404: No such object: ###/deltest.txt, notFound\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618178515
  }
  {
    "name": "root",
    "levelname": "ERROR",
    "severity": "ERROR",
    "message": "SetInodeAttributes: input/output error, SetMtime: UpdateObject: not retrying UpdateObject(\"###/deltest.txt\"): gcs.NotFoundError: googleapi: Error 404: No such object: ###/deltest.txt, notFound\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618219465
  }
  {
    "name": "root",
    "levelname": "DEBUG",
    "severity": "DEBUG",
    "message": "fuse_debug: Op 0x000037c8        connection.go:500] -> Error: \"input/output error\"\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618257045
  }
  {
    "name": "root",
    "levelname": "ERROR",
    "severity": "ERROR",
    "message": "fuse: *fuseops.SetInodeAttributesOp error: input/output error\n",
    "timestampSeconds": 1649408345,
    "timestampNanos": 618267145
  }
  • Could you please add --implicit-dirs option in the gcsfuse mount command and redo the tests? Do you observe the same behaviour? – AviD Apr 11 '22 at 15:20
  • @AviD I've added the --implicit-dirs flag as suggested but the behaviour stays exactly the same. – lawrenceB Apr 12 '22 at 08:48

0 Answers0