Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Deleted files returning 200 #850

Closed
mooncake4132 opened this Issue Jan 25, 2019 · 11 comments

Comments

Projects
None yet
2 participants
@mooncake4132
Copy link

mooncake4132 commented Jan 25, 2019

Describe the bug
Seaweedfs returns 200 on deleted files. It should be returning 404s.

System Setup
I verified this still works on 1.01, but fails in the latest 1.23 (on Windows). Our integration tests which uses seaweedfs:latest (on Linux) started failing on this issue a few days ago, so I suspect this issue only appeared in the recent releases.

Expected behavior
This is a manual capture of 1.01 running on Windows:

>type test.txt
test

>curl http://localhost:9333/dir/assign
{"fid":"28,1699fcd3c502","url":"localhost:8080","publicUrl":"localhost:8080","count":1}

>curl http://127.0.0.1:8080/28,1699fcd3c502 -vv
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /28,1699fcd3c502 HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.55.1
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Date: Fri, 25 Jan 2019 04:00:01 GMT
< Content-Length: 0
<
* Connection #0 to host 127.0.0.1 left intact

>curl -F file=@test.txt http://127.0.0.1:8080/28,1699fcd3c502
{"name":"test.txt","size":28}

>curl http://127.0.0.1:8080/28,1699fcd3c502
test

>curl -X DELETE http://127.0.0.1:8080/28,1699fcd3c502
{"size":58}

>curl http://127.0.0.1:8080/28,1699fcd3c502 -vv
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /28,1699fcd3c502 HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.55.1
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Date: Fri, 25 Jan 2019 04:00:52 GMT
< Content-Length: 0
<
* Connection #0 to host 127.0.0.1 left intact

Note that it returns 404 Not Found at the very end.

Actual Behavior
This is a manual capture of 1.23 running on Windows:

>curl http://localhost:9333/dir/assign
{"fid":"4,01a6e2d9df","url":"172.17.0.3:8080","publicUrl":"localhost:8080","count":1}

>curl http://127.0.0.1:8080/4,01a6e2d9df -vv
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /4,01a6e2d9df HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.55.1
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Date: Thu, 24 Jan 2019 22:07:39 GMT
< Content-Length: 0
<
* Connection #0 to host 127.0.0.1 left intact

>curl -F file=@test.txt http://127.0.0.1:8080/4,01a6e2d9df
{"name":"test.txt","size":4,"eTag":"7e104253"}
>curl http://127.0.0.1:8080/4,01a6e2d9df
test

>curl -X DELETE http://127.0.0.1:8080/4,01a6e2d9df
{"size":58}

>curl http://127.0.0.1:8080/4,01a6e2d9df -vv
*   Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /4,01a6e2d9df HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/7.55.1
> Accept: */*
>
< HTTP/1.1 200 OK
< Accept-Ranges: bytes
< Content-Length: 0
< Etag: "00000000"
< Date: Thu, 24 Jan 2019 22:08:25 GMT

Note that this returns a 200 OK despite having deleted the file.

@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 25, 2019

This is changed because "weed filer" also uses this.

If using 404, the delete operation is considered failure. there are no way to tell it is a "good" deletion or "bad" deletion.

@mooncake4132

This comment has been minimized.

Copy link
Author

mooncake4132 commented Jan 25, 2019

I don't use filer myself so I may be understanding it wrong, but shouldn't 404 be considered a good deletion and 200 considered a failed deletion?

Currently my program checks the HTTP status code to determine if a file exists. Now that there's two states:

HTTP/1.1 404 Not Found
< Date: Fri, 25 Jan 2019 04:00:52 GMT
< Content-Length: 0
HTTP/1.1 200 OK
< Accept-Ranges: bytes
< Content-Length: 0
< Etag: "00000000"
< Date: Thu, 24 Jan 2019 22:08:25 GMT

Does that mean to determine whether a file exist I should check status_code == 404 or (status_code == 200 and etag == '00000000') ?

@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 25, 2019

seems I misunderstood some part. Here is what I ran on Mac with latest version, same behavior as 1.23. Is that what you expected?

$ curl -F file=@overview.pdf "http://localhost:8080/5,1249301675"
{"name":"overview.pdf","size":51658,"eTag":"8742f056"}

$ curl -X DELETE "http://localhost:8080/5,1249301675"
{"size":44196}

$ curl -v  "http://localhost:8080/5,1249301675"
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8080 (#0)
> GET /5,1249301675 HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.54.0
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Date: Fri, 25 Jan 2019 22:13:12 GMT
< Content-Length: 0
<
* Connection #0 to host localhost left intact
@mooncake4132

This comment has been minimized.

Copy link
Author

mooncake4132 commented Jan 25, 2019

Yes, that is what I would expect. Is this only failing on Linux and Windows?

@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 25, 2019

This is what I ran on linux:

chris@ubuntu18:~$ curl "http://localhost:9333/dir/assign"
{"fid":"2,02ba31655e","url":"localhost:7777","publicUrl":"localhost:7777","count":1}chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$ curl -F file=@x.txt "http://localhost:7777/2,02ba31655e"
{"name":"x.txt","size":30,"eTag":"438aa3f8"}chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$
chris@ubuntu18:~$ curl -v  "http://localhost:7777/2,02ba31655e"
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 7777 (#0)
> GET /2,02ba31655e HTTP/1.1
> Host: localhost:7777
> User-Agent: curl/7.61.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Accept-Ranges: bytes
< Content-Disposition: inline; filename="x.txt"
< Content-Length: 30
< Content-Type: text/plain
< Etag: "438aa3f8"
< Last-Modified: Fri, 25 Jan 2019 18:19:00 GMT
< Date: Fri, 25 Jan 2019 18:19:14 GMT
<
sdfadsf
asdf
asdf
a
sdf
asd
f
* Connection #0 to host localhost left intact
chris@ubuntu18:~$ curl -X DELETE  "http://localhost:7777/2,02ba31655e"
{"size":69}chris@ubuntu18:~$
chris@ubuntu18:~$ curl -v  "http://localhost:7777/2,02ba31655e"
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 7777 (#0)
> GET /2,02ba31655e HTTP/1.1
> Host: localhost:7777
> User-Agent: curl/7.61.0
> Accept: */*
>
< HTTP/1.1 404 Not Found
< Date: Fri, 25 Jan 2019 18:19:24 GMT
< Content-Length: 0
<
* Connection #0 to host localhost left intact
@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 25, 2019

this part of code is the same for any os.

@mooncake4132

This comment has been minimized.

Copy link
Author

mooncake4132 commented Jan 25, 2019

I'm able to reproduce this completely fresh on Linux. (Our integration tests also reproduced this with the docker build seaweedfs:latest.)

Am I doing something wrong?

~/weed$ cat /etc/issue
Ubuntu 16.04.3 LTS \n \l

~/weed$ wget https://github.com/chrislusf/seaweedfs/releases/download/1.23/linux_amd64.tar.gz 2>/dev/null

~/weed$ ls
linux_amd64.tar.gz

~/weed$ tar zxvf linux_amd64.tar.gz
weed

~/weed$ mkdir data

~/weed$ ./weed server -master.port=19333 -volume.port=18080 -volume.max=1000 -dir=data > weed_logs.txt 2>&1 &
[1] 106

~/weed$ echo -e "asfafsaf\n\asdfs" > test.txt

~/weed$ curl http://localhost:19333/dir/assign
{"fid":"4,0127cd4736","url":"localhost:18080","publicUrl":"localhost:18080","count":1}

~/weed$ curl -F file=@test.txt "http://localhost:18080/4,0127cd4736"
{"name":"test.txt","size":15,"eTag":"34ed43d2"}

~/weed$ curl -X DELETE "http://localhost:18080/4,0127cd4736"
{"size":69}

~/weed$ curl http://localhost:18080/4,0127cd4736 -vvv
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 18080 (#0)
> GET /4,0127cd4736 HTTP/1.1
> Host: localhost:18080
> User-Agent: curl/7.47.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Accept-Ranges: bytes
< Content-Length: 0
< Etag: "00000000"
< Date: Fri, 25 Jan 2019 22:42:09 GMT
<
* Connection #0 to host localhost left intact

weed_logs.txt

I0125 14:35:46   106 file_util.go:19] Folder data Permission: -rwxrwxrwx
I0125 14:35:46   106 master_server.go:68] Volume Size Limit is 30000 MB
I0125 14:35:46   106 server.go:176] Start Seaweed Master 1.23 at localhost:19333
I0125 14:35:46   106 server.go:197] Start Seaweed Master 1.23 grpc server at localhost:29333
I0125 14:35:46   106 raft_server.go:47] Starting RaftServer with localhost:19333
I0125 14:35:49   106 raft_server.go:88] current cluster leader: localhost:19333
I0125 14:35:49   106 master_server.go:102] [ localhost:19333 ] I am the leader!
I0125 14:35:49   106 file_util.go:19] Folder data Permission: -rwxrwxrwx
I0125 14:35:49   106 disk_location.go:106] Store started on dir: data with 0 volumes max 1000
I0125 14:35:49   106 volume.go:158] Start Seaweed volume server 1.23 at 0.0.0.0:18080
I0125 14:35:49   106 volume_grpc_client_to_master.go:19] Volume server start with masters: [localhost:19333]
I0125 14:35:49   106 volume_grpc_client_to_master.go:58] Heartbeat to: localhost:19333
I0125 14:35:49   106 node.go:223] topo adds child DefaultDataCenter
I0125 14:35:49   106 node.go:223] topo:DefaultDataCenter adds child DefaultRack
I0125 14:35:49   106 node.go:223] topo:DefaultDataCenter:DefaultRack adds child localhost:18080
I0125 14:35:49   106 master_grpc_server.go:67] added volume server localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:1 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/1.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 1 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:2 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/2.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 2 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:3 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/3.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 3 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:4 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/4.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 4 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:5 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/5.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 5 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:6 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/6.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 6 on topo:DefaultDataCenter:DefaultRack:localhost:18080
I0125 14:36:23   106 store.go:96] In dir data adds volume:7 collection: replicaPlacement:000 ttl:
I0125 14:36:23   106 volume_loading.go:79] loading index data/7.idx to memory readonly false
I0125 14:36:23   106 volume_growth.go:205] Created Volume 7 on topo:DefaultDataCenter:DefaultRack:localhost:18080
@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 25, 2019

can not tell anything special. maybe "curl" version?

@mooncake4132

This comment has been minimized.

Copy link
Author

mooncake4132 commented Jan 25, 2019

I'll see if I can find the offending commit with git bisect. I never worked with go before so I'll have to figure out how to build it first.

@mooncake4132

This comment has been minimized.

Copy link
Author

mooncake4132 commented Jan 26, 2019

Oops, accidentally replied with my friends account.

It seems like badd8fd is the issue. Reverting that from master solves the problem. Below is the (relevant) verbose log after I reverted the change.

I0125 21:20:09 13547 volume_read_write.go:80] writing needle 1,0127cd4736
I0125 21:20:09 13547 volume_read_write.go:111] delete needle 1,0127cd4736
I0125 21:20:09 13547 volume_server_handlers_read.go:42] volume 1 reading 0127cd4736 Size:0, DataSize:0, Name:, Mime:
I0125 21:20:09 13547 volume_server_handlers_read.go:69] read bytes 0 error File Entry Not Found. offset 8, Needle id 1 expected size 58 Memory 0
I0125 21:20:09 13547 volume_server_handlers_read.go:71] read /1,0127cd4736 error: File Entry Not Found. offset 8, Needle id 1 expected size 58 Memory 0

Apparently the deleted file has a size of zero, and thus would short-circuit to your if statement in the commit and return with no error.

@chrislusf chrislusf closed this in 5668ed7 Jan 26, 2019

@chrislusf

This comment has been minimized.

Copy link
Owner

chrislusf commented Jan 26, 2019

Thanks a lot!!!

I added a fix for this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.