weed mount with TLS

[thaines]

Describe the bug
seaweed mount doesn't work when gRPC is secured via TLS. (i.e. works if I comment out the grpc lines in security.toml, leaving disableHttp options and jwt key, but breaks if those lines are left in). This may be a misunderstanding of what does/does not work right now on my part, but I interpreted the security documentation as at least implying this would work (and everything except for mount does).

System Setup

weed -logdir=/var/log/seaweed/master master -mdir=/var/lib/seaweedfs -ip=192.168.108.119 -disableHttp
weed -logdir=/var/log/seaweed/volume volume -port=9380 -dir=/mnt/seaweed000/data -max=50 -ip=192.168.108.119 -mserver=192.168.108.119:9333 -dataCenter=Room -rack=Rack1
weed -logdir=/var/log/seaweed/filer filer -ip=192.168.108.119 -port=8888 -master=192.168.108.119:9333 -disableHttp
weed -logdir=/var/log/seaweed/mount mount -filer=192.168.108.119:8888 -dir=/mnt/seaweed

OS = Ubuntu 20.04 LTS (very fresh install - only setup done prior to this was Cassandra, for the db)
Weed = version 30GB 2.18 d2ead72 linux amd64
(initially tried 2.16 - same issue)

filer.toml:

[filer.options]
recursive_delete = false

[cassandra]
enabled = true
keyspace="seaweed"
hosts=["localhost:9042",]
username="seaweed"
password="***"

security.toml

[jwt.signing]
key = "***"

[grpc]
ca = "/etc/seaweedfs/out/hex.crt"

[grpc.volume]
cert = "/etc/seaweedfs/out/volume.crt"
key  = "/etc/seaweedfs/out/volume.key"

[grpc.master]
cert = "/etc/seaweedfs/out/master.crt"
key  = "/etc/seaweedfs/out/master.key"

[grpc.filer]
cert = "/etc/seaweedfs/out/filer.crt"
key  = "/etc/seaweedfs/out/filer.key"

[grpc.client]
cert = "/etc/seaweedfs/out/client.crt"
key  = "/etc/seaweedfs/out/client.key"

with above certificates created by following instructions in wiki.

master log:

Log file created at: 2020/12/29 11:56:50
Running on machine: jeannie
Binary: Built with gc go1.15.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss threadid file:line] msg
I1229 11:56:50 03374 file_util.go:23] Folder /var/lib/seaweedfs Permission: -rwxr-xr-x
I1229 11:56:50 03374 master.go:168] current: 192.168.108.119:9333 peers:
I1229 11:56:50 03374 master_server.go:107] Volume Size Limit is 30000 MB
I1229 11:56:50 03374 master_server.go:192] adminScripts:
I1229 11:56:50 03374 master.go:122] Start Seaweed Master 30GB 2.18 d2ead72 at 0.0.0.0:9333
I1229 11:56:50 03374 raft_server.go:70] Starting RaftServer with 192.168.108.119:9333
I1229 11:56:50 03374 raft_server.go:129] current cluster leader: 
I1229 11:56:50 03374 master.go:146] Start Seaweed Master 30GB 2.18 d2ead72 grpc server at 0.0.0.0:19333
I1229 11:56:52 03374 masterclient.go:78] No existing leader found!
I1229 11:56:52 03374 raft_server.go:154] Initializing new cluster
I1229 11:56:52 03374 master_server.go:141] leader change event:  => 192.168.108.119:9333
I1229 11:56:52 03374 master_server.go:143] [ 192.168.108.119:9333 ] 192.168.108.119:9333 becomes leader.
I1229 11:56:55 03374 masterclient.go:126] redirected to leader 192.168.108.119:9333
I1229 11:56:55 03374 master_grpc_server.go:250] + client master@192.168.108.119:52234
I1229 11:59:08 03374 node.go:278] topo adds child Room
I1229 11:59:08 03374 node.go:278] topo:Room adds child Rack1
I1229 11:59:08 03374 node.go:278] topo:Room:Rack1 adds child 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:73] added volume server 192.168.108.119:9380
I1229 11:59:08 03374 volume_layout.go:352] Volume 3 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 4 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 5 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 2 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 1 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 6 becomes writable
I1229 11:59:08 03374 volume_layout.go:352] Volume 7 becomes writable
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 3 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 4 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 5 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 2 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 1 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 6 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:110] master see new volume 7 from 192.168.108.119:9380
I1229 11:59:08 03374 master_grpc_server.go:155] master send to master@192.168.108.119:52234: url:"192.168.108.119:9380" public_url:"192.168.108.119:9380" new_vids:3 new_vids:4 new_vids:5 new_vids:2 new_vids:1 new_vids:6 new_vids:7 data_center:"Room"
I1229 12:01:02 03374 master_grpc_server.go:250] + client filer@192.168.108.119:8888

volume log:

Log file created at: 2020/12/29 11:59:08
Running on machine: jeannie
Binary: Built with gc go1.15.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss threadid file:line] msg
I1229 11:59:08 03489 file_util.go:23] Folder /mnt/seaweed000/data Permission: -rwxr-x---
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/2.idx to memory
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/1.idx to memory
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/2.dat, replicaPlacement=000 v=3 size=8 ttl=
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/6.idx to memory
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/7.idx to memory
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/3.idx to memory
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/1.dat, replicaPlacement=000 v=3 size=232 ttl=
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/6.dat, replicaPlacement=000 v=3 size=384 ttl=
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/4.idx to memory
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/7.dat, replicaPlacement=000 v=3 size=784 ttl=
I1229 11:59:08 03489 volume_loading.go:123] loading index /mnt/seaweed000/data/5.idx to memory
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/3.dat, replicaPlacement=000 v=3 size=152 ttl=
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/4.dat, replicaPlacement=000 v=3 size=8 ttl=
I1229 11:59:08 03489 disk_location.go:131] data file /mnt/seaweed000/data/5.dat, replicaPlacement=000 v=3 size=576 ttl=
I1229 11:59:08 03489 disk_location.go:173] Store started on dir: /mnt/seaweed000/data with 7 volumes max 50
I1229 11:59:08 03489 disk_location.go:176] Store started on dir: /mnt/seaweed000/data with 0 ec shards
I1229 11:59:08 03489 volume_grpc_client_to_master.go:52] Volume server start with seed master nodes: [192.168.108.119:9333]
I1229 11:59:08 03489 volume.go:334] Start Seaweed volume server 30GB 2.18 d2ead72 at 0.0.0.0:9380
I1229 11:59:08 03489 volume_grpc_client_to_master.go:114] Heartbeat to: 192.168.108.119:9333

filer log:

Log file created at: 2020/12/29 12:01:02
Running on machine: jeannie
Binary: Built with gc go1.15.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss threadid file:line] msg
W1229 12:01:02 03561 filer_server.go:114] skipping default store dir in ./filerldb2
I1229 12:01:02 03561 filer.go:101] existing filer.store.id = 921739869
I1229 12:01:02 03561 configuration.go:28] configured filer store to cassandra
I1229 12:01:02 03561 filer.go:173] Start Seaweed Filer 30GB 2.18 d2ead72 at 192.168.108.119:8888
I1229 12:01:03 03561 filer_grpc_server_sub_meta.go:182] + listener filer:192.168.108.119:8888@192.168.108.119:49218
I1229 12:01:03 03561 filer_grpc_server_sub_meta.go:70]  filer:192.168.108.119:8888@192.168.108.119:49218 local subscribe / from 2020-12-29 12:00:02.42229329 +0000 UTC
I1229 12:01:03 03561 filer_grpc_server_sub_meta.go:85] after local log reads, filer:192.168.108.119:8888@192.168.108.119:49218 local subscribe / from 2020-12-29 12:00:02.42229329 +0000 UTC

Mount doesn't output anything at all (doesn't even create a log file) or result in a mount point appearing. Afraid I have no experience of go or debugging it, but strace shows all but two of the many threads are just sitting there, waiting for a mutex (worker threads?), while one thread seems to be waiting for a mutex, timing out, sleeping and then waiting again (main thread?) and finally another thread is polling the 4 sockets it has opened, timing out, then polling again and so on (networking thread?). Which is to say at the system level it looks like about what you would expect!

Expected behaviour
To mount! They key detail I note is that commenting out all of the [grpc] blocks in security.toml results in it working. Also, with certificates weed shell works fine, and if I enable the web interface of filer then I can upload/download files as expected - enabling certificates seems to only affect mount.

Even if this is an expected failure mode, it would still be very helpful for something to be outputted to the log, such that I can see what has gone wrong.

Additional context
I am doing this "properly", as in putting weed at /usr/local/bin/weed, setting everything up as services with systemctl and running all the processes as a user I've created called seaweed, except for the mount process which is root because of the shared access/fuse issue. Mentioning in case it's getting stuck trying to write a log file somewhere it has no permission to do so! It does have permission to write in it's current working directory when started (I've used /var/lib/seaweedfs for all of them; no idea if that is wise but did try a different directory for mount just incase). Have triple checked permissions on everything and all looks correct.

[chrislusf]

Thanks for the detailed issue content!

I can reproduce this and found it was caused by a regression. Added a fix.

[thaines]

Thank you for the speedy response - that's brilliant!