fuse client the alluxio worker doesn't go through short-circuit in the same node in Kubernetes #9089

cheyang · 2019-05-13T22:30:44Z

Alluxio Version:
2.0.0-snapshot

Describe the bug
Deploy master, workers and fuse in Kubernetes.

And go to the machine A(192.168.0.109), copy whole the directory from alluxio to local directory

time cp -r /alluxio-fuse/training-data/images /var/lib/docker/test

But I noticed the file is not located in the same node, it's in 192.168.0.110:

/opt/alluxio/bin/alluxio fs stat /training-data/images/validation-00108-of-00128
/training-data/images/validation-00108-of-00128 is a file path.
FileInfo{fileId=35802578943, name=validation-00108-of-00128, path=/training-data/images/validation-00108-of-00128, ufsPath=oss://imagenet-huabei5/images/validation-00108-of-00128, length=50475323, blockSizeBytes=536870912, creationTimeMs=1557791864620, completed=true, folder=false, pinned=false, cacheable=true, persisted=true, blockIds=[35785801728], inMemoryPercentage=0, lastModificationTimesMs=1557109076000, ttl=-1, ttlAction=DELETE, owner=, group=, mode=511, persistenceState=PERSISTED, mountPoint=false, replicationMax=-1, replicationMin=0, fileBlockInfos=[FileBlockInfo{blockInfo=BlockInfo{id=35785801728, length=50475323, locations=[BlockLocation{workerId=4272994094758843366, address=WorkerNetAddress{host=192.168.0.110, rpcPort=29998, dataPort=29998, webPort=29996, domainSocketPath=/opt/domain/2956ad2e-f596-4cbb-a31e-9a92d934b6d4, tieredIdentity=TieredIdentity(node=192.168.0.110, rack=null)}, tierAlias=SSD}]}, offset=0, ufsLocations=[]}], mountId=344496208015086572, inAlluxioPercentage=100, ufsFingerprint=TYPE|FILE UFS|oss OWNER|_ GROUP|_ MODE|511 CONTENT_HASH|373069F926A32F9FAF9DA7B4E36A0B34 , acl=user::rwx,group::rwx,other::rwx, defaultAcl=}
Containing the following blocks:
BlockInfo{id=35785801728, length=50475323, locations=[BlockLocation{workerId=4272994094758843366, address=WorkerNetAddress{host=192.168.0.110, rpcPort=29998, dataPort=29998, webPort=29996, domainSocketPath=/opt/domain/2956ad2e-f596-4cbb-a31e-9a92d934b6d4, tieredIdentity=TieredIdentity(node=192.168.0.110, rack=null)}, tierAlias=SSD}]}

To Reproduce
Steps to reproduce the behavior (as minimally and precisely as possible)

Expected behavior
A clear and concise description of what you expected to happen.

Urgency
Describe the impact and urgency of the bug.

Additional context
Add any other context about the problem here.

The text was updated successfully, but these errors were encountered:

cheyang · 2019-05-13T22:45:03Z

ping @madanadit

cheyang · 2019-05-14T02:24:17Z

/ping @apc999. Since @madanadit is on travel, may I know who else can help investigate?

cheyang · 2019-05-15T21:53:11Z

When I tried to copy the file again.

time cp  /alluxio-fuse/training-data/images/train-00766-of-01024 /var/lib/test/
cp: overwrite ‘/var/lib/test/train-00766-of-01024’? y
cp: error reading ‘/alluxio-fuse/training-data/images/train-00766-of-01024’: Input/output error
cp: failed to extend ‘/var/lib/test/train-00766-of-01024’: Input/output error

real    0m4.592s
user    0m0.001s
sys     0m0.002s

I see the error from the logging of the fuse:

2019-05-15 21:48:04,279 WARN  GrpcBlockingStream - Received error io.grpc.StatusRuntimeException: UNAUTHENTICATED: Channel: 612ded02-efa0-4792-8589-f3c0c60d5872 is not authenticated for call: alluxio.grpc.block.BlockWorker/ReadBlock for stream (GrpcDataReader{request=block_id: 25870467072
offset: 0
length: 146128878
promote: true
chunk_size: 1048576
open_ufs_block_options {
  ufs_path: "oss://imagenet-huabei5/images/train-00541-of-01024"
  offset_in_file: 0
  block_size: 146128878
  maxUfsReadConcurrency: 2147483647
  mountId: 344496208015086572
  no_cache: false
}
, address=WorkerNetAddress{host=192.168.0.110, rpcPort=29998, dataPort=29998, webPort=29996, domainSocketPath=/opt/domain/2956ad2e-f596-4cbb-a31e-9a92d934b6d4, tieredIdentity=TieredIdentity(node=192.168.0.110, rack=null)}})
2019-05-15 21:48:04,280 ERROR AlluxioFuseFileSystem - Failed to read file /training-data/images/train-00541-of-01024
alluxio.exception.status.UnauthenticatedException: Channel: 612ded02-efa0-4792-8589-f3c0c60d5872 is not authenticated for call: alluxio.grpc.block.BlockWorker/ReadBlock (GrpcDataReader{request=block_id: 25870467072
offset: 0
length: 146128878
promote: true
chunk_size: 1048576
open_ufs_block_options {
  ufs_path: "oss://imagenet-huabei5/images/train-00541-of-01024"
  offset_in_file: 0
  block_size: 146128878
  maxUfsReadConcurrency: 2147483647
  mountId: 344496208015086572
  no_cache: false
}

In the logs of worker, I'm able to see the error:

SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$ServerTransportListenerImpl$1StreamCreated@d8514a5
io.grpc.StatusRuntimeException: UNAUTHENTICATED: alluxio.exception.AccessControlException: The client user is not authorized so as to be null in server
	at io.grpc.Status.asRuntimeException(Status.java:521)
	at alluxio.worker.grpc.BlockWorkerImpl.getAuthenticatedUserInfo(BlockWorkerImpl.java:178)
	at alluxio.worker.grpc.BlockWorkerImpl.readBlock(BlockWorkerImpl.java:106)
	at alluxio.grpc.BlockWorkerGrpc$MethodHandlers.invoke(BlockWorkerGrpc.java:544)
	at io.grpc.stub.ServerCalls$StreamingServerCallHandler.startCall(ServerCalls.java:221)
	at alluxio.security.authentication.AuthenticatedUserInjector.interceptCall(AuthenticatedUserInjector.java:63)
	at io.grpc.ServerInterceptors$InterceptCallHandler.startCall(ServerInterceptors.java:229)
	at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.startWrappedCall(ServerImpl.java:563)
	at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.startCall(ServerImpl.java:544)
	at io.grpc.internal.ServerImpl$ServerTransportListenerImpl.access$1800(ServerImpl.java:364)
	at io.grpc.internal.ServerImpl$ServerTransportListenerImpl$1StreamCreated.runInContext(ServerImpl.java:480)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

May 15, 2019 10:04:38 PM io.grpc.internal.SerializingExecutor run
SEVERE: Exception while executing runnable io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed@77d7fd5
java.lang.IllegalStateException: call already closed
	at com.google.common.base.Preconditions.checkState(Preconditions.java:507)
	at io.grpc.internal.ServerCallImpl.close(ServerCallImpl.java:172)
	at alluxio.security.authentication.AuthenticatedUserInjector.authenticateCall(AuthenticatedUserInjector.java:98)
	at alluxio.security.authentication.AuthenticatedUserInjector.access$000(AuthenticatedUserInjector.java:34)
	at alluxio.security.authentication.AuthenticatedUserInjector$1.onHalfClose(AuthenticatedUserInjector.java:66)
	at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:283)
	at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:710)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

apc999 · 2019-05-15T23:02:10Z

@bf8086 this looks like some gRPC authentication failure. Can you take a look and see if it is gRPC related?

LuQQiu · 2019-05-15T23:05:31Z

Alluxio fuse client does not allow overwrite since Alluxio is a write once read many times filesystem. If need to overwrite, delete the file first.

apc999 · 2019-05-15T23:09:35Z

@cheyang I think we are talking about two problems in this issue ticket

locality not enforced, @madanadit can help once he is back
failed overwrite -- from what @LuQQiu said, this is not supported by Alluxio fuse. Though we might want to have a better warning/error messages. @LuQQiu is it possible?

bf8086 · 2019-05-15T23:57:46Z

For the authentication error, looks like the authenticated client user is set to null on the server side. @ggezer Do you have any idea when the client user can be null?

cheyang · 2019-05-16T00:24:22Z

Alluxio fuse client does not allow overwrite since Alluxio is a write once read many times filesystem. If need to overwrite, delete the file first.

I have tried. The same error:

time cp  /alluxio-fuse/training-data/images/train-00766-of-01024 /
cp: error reading ‘/alluxio-fuse/training-data/images/train-00766-of-01024’: Input/output error
cp: failed to extend ‘/train-00766-of-01024’: Input/output error

Notice:

/alluxio-fuse/training-data/images/train-00766-of-01024 is alluxio fuse mount point
/ is local directory

Btw, It looks good when I'm using CLI inside the fuse pod in the same node:

# kubectl get po -owide | grep 109| grep fuse
alluxio-fuse-wqj57     1/1     Running   0          2d    192.168.0.109   cn-huhehaote.192.168.0.109   <none>

# kubectl exec -it alluxio-fuse-wqj57 bash
/opt/alluxio/bin/alluxio fs cp /training-data/images/train-00766-of-01024 /test
Copied /training-data/images/train-00766-of-01024 to /test

LuQQiu · 2019-05-16T20:39:28Z

The fuse has one issue is that the output message is always not informative (we could only return error code and different platforms have different interpretation ways). All the detailed error message is in fuse.log. What's the error message of your new try? Is it the same as before?

cheyang · 2019-05-16T23:09:20Z

The error is as below:

2019-05-16 23:08:15,219 WARN  DefaultBlockWorkerClient - Error sending async cache request block_id: 29645340672
source_host: "192.168.0.110"
source_port: 29998
open_ufs_block_options {
  ufs_path: "oss://imagenet-huabei5/images/train-00766-of-01024"
  offset_in_file: 0
  block_size: 149593686
  maxUfsReadConcurrency: 2147483647
  mountId: 344496208015086572
  no_cache: false
}
length: 149593686
 to worker alluxio.grpc.GrpcServerAddress@32d59436.
io.grpc.StatusRuntimeException: UNAUTHENTICATED: Channel: ab036f85-f359-4afb-b05e-7a4856e7c64f is not authenticated for call: alluxio.grpc.block.BlockWorker/AsyncCache
	at io.grpc.Status.asRuntimeException(Status.java:530)
	at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:434)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at alluxio.grpc.GrpcChannel$ChannelResponseTracker$1$1.onClose(GrpcChannel.java:123)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:694)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:397)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:459)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:546)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:467)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:584)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

apc999 · 2019-05-16T23:14:18Z

@bf8086 @ggezer can you take a look a the GRPC issue on UNAUTHENTICATED? Why fuse request sees this error?

bf8086 · 2019-05-17T02:21:46Z

Looks like the channel id is not recognized by gRPC server.

@cheyang Does the error happen consistently? Did you restart any Alluxio worker before seeing this issue?

cheyang · 2019-05-17T06:42:08Z

It happens consistently. I didn't see any restart:

kubectl get po
NAME                   READY   STATUS    RESTARTS   AGE
alluxio-fuse-bwj29     1/1     Running   0          3d6h
alluxio-fuse-ptfnm     1/1     Running   0          3d6h
alluxio-fuse-tz7c7     1/1     Running   0          3d6h
alluxio-fuse-wqj57     1/1     Running   0          3d6h
alluxio-master-0       1/1     Running   0          3d6h
alluxio-worker-d57dv   1/1     Running   0          3d6h
alluxio-worker-df42b   1/1     Running   0          3d6h
alluxio-worker-k47nr   1/1     Running   0          3d6h
alluxio-worker-p4bh4   1/1     Running   0          3d6h

ggezer · 2019-05-21T04:02:37Z

Worker will revoke authentication for a client following a period of inactivity. (Default 60mins) Authentication failires are currently not handled by blockworker clients, thus authentication failure become permanent. Looks like Fuse can retain a client with long periods of inactivity. This will need to be fixed.

ggezer · 2019-05-21T04:07:19Z

Discussed this with @bf8086. The most viable solution, without incurring any perf loss, is to keep authentication call active on the server and close it whenever authentication is being revoked due to inactivity. This will introduce 1 more round trip to Sasl traffic for letting client continue, but server will retain the call reference for failing/closing it later. That way client will get notified lazily of a need to reauthenticate. With this solution there could be intermittent failures with the blockworker client but those will be propagated to application so it shouldn't cause any inconsistencies.

cheyang · 2019-05-22T00:44:21Z

What's your suggestions on workaround? Just umount and remount the fuse?

bf8086 · 2019-05-23T00:31:34Z

@cheyang Can you try setting alluxio.security.stale.channel.purge.interval=365d to see if that helps to keep the client channel authenticated?

madanadit · 2019-05-25T20:12:07Z

fix for locality: #9143

mingfang · 2019-05-28T13:07:50Z

Thanks @bf8086 setting alluxio.security.stale.channel.purge.interval=365d works.

I'll file a separate issue to track this bug.

`AuthenticationServer` has a setting for revoking authentication after a period of inactivity. To handle that on the client side, metadata clients, after a period of inactivity, will retry after getting `Unauthenticated` code. However, due to nature of streaming, data clients can not retry after getting the error because they might have pipelined more data before seeing the error. And since this revocation will not change the connection state, they used to continue getting `Unauthenticated`. See #9089 for an instance of this problem. This PR introduces long polling to authentication handshake. Client and server will not complete streams used for authentication and instead will use it for notifying end of an authentication session. With this change, revocation on server will be propagated to client channel via health status, causing a client recreation for later use of the same channel. Also client closing the channel will notify server and it'll clean its state of the recently closed channel. Periodic cleanup has not been disabled in order to not prolong a duration for a channel to remain authenticated. pr-link: #9149 change-id: cid-7c847b674046f4836c2d77881d47985a760b8951

ggezer · 2019-06-03T23:53:32Z

@cheyang @mingfang You can try the new RC2 build to see if you have this solved without manually setting the purge interval.

bf8086 · 2019-06-04T00:04:30Z

The PR did not make it to the official RC2 release. In order to try it you will have to build from the latest branch-2.0 or master branch.

mingfang · 2019-06-10T11:21:59Z

@ggezer @bf8086 The FUSE idle problems seems to be fixed in v2.0.0-RC3.
I no longer have to set alluxio.security.stale.channel.purge.interval=365d and the mount continues to work after idling overnight.

bf8086 · 2019-06-10T20:32:21Z

@mingfang Great to hear the issue is verified fixed in your deployment!

cheyang · 2019-06-30T22:06:47Z

Thanks, it's fixed alluxio 2.0.

cheyang added the type-bug This issue is about a bug label May 13, 2019

apc999 added area-fuse Alluxio fuse integration area-k8s Alluxio Kubernetes Integration priority-high labels May 15, 2019

apc999 added the target-2.0.0 label May 15, 2019

ggezer mentioned this issue May 28, 2019

Implement authentication long polling #9149

Merged

mingfang mentioned this issue May 28, 2019

FUSE mount fails after 60mins of inactivity. #9150

Closed

cheyang closed this as completed Jun 30, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fuse client the alluxio worker doesn't go through short-circuit in the same node in Kubernetes #9089

fuse client the alluxio worker doesn't go through short-circuit in the same node in Kubernetes #9089

cheyang commented May 13, 2019 •

edited

cheyang commented May 13, 2019

cheyang commented May 14, 2019

cheyang commented May 15, 2019 •

edited

apc999 commented May 15, 2019 •

edited

LuQQiu commented May 15, 2019

apc999 commented May 15, 2019

bf8086 commented May 15, 2019

cheyang commented May 16, 2019

LuQQiu commented May 16, 2019 •

edited

cheyang commented May 16, 2019 •

edited

apc999 commented May 16, 2019

bf8086 commented May 17, 2019

cheyang commented May 17, 2019

ggezer commented May 21, 2019

ggezer commented May 21, 2019

cheyang commented May 22, 2019

bf8086 commented May 23, 2019

madanadit commented May 25, 2019

mingfang commented May 28, 2019

ggezer commented Jun 3, 2019

bf8086 commented Jun 4, 2019

mingfang commented Jun 10, 2019

bf8086 commented Jun 10, 2019

cheyang commented Jun 30, 2019

fuse client the alluxio worker doesn't go through short-circuit in the same node in Kubernetes #9089

fuse client the alluxio worker doesn't go through short-circuit in the same node in Kubernetes #9089

Comments

cheyang commented May 13, 2019 • edited

cheyang commented May 13, 2019

cheyang commented May 14, 2019

cheyang commented May 15, 2019 • edited

apc999 commented May 15, 2019 • edited

LuQQiu commented May 15, 2019

apc999 commented May 15, 2019

bf8086 commented May 15, 2019

cheyang commented May 16, 2019

LuQQiu commented May 16, 2019 • edited

cheyang commented May 16, 2019 • edited

apc999 commented May 16, 2019

bf8086 commented May 17, 2019

cheyang commented May 17, 2019

ggezer commented May 21, 2019

ggezer commented May 21, 2019

cheyang commented May 22, 2019

bf8086 commented May 23, 2019

madanadit commented May 25, 2019

mingfang commented May 28, 2019

ggezer commented Jun 3, 2019

bf8086 commented Jun 4, 2019

mingfang commented Jun 10, 2019

bf8086 commented Jun 10, 2019

cheyang commented Jun 30, 2019

cheyang commented May 13, 2019 •

edited

cheyang commented May 15, 2019 •

edited

apc999 commented May 15, 2019 •

edited

LuQQiu commented May 16, 2019 •

edited

cheyang commented May 16, 2019 •

edited