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

go客户端设置了接口超时时间,在java 服务端无法获取到正确的值 #2546

Closed
Jafeyyu opened this issue Dec 26, 2023 · 9 comments
Labels
bug Something isn't working waiting-for-feedback

Comments

@Jafeyyu
Copy link
Contributor

Jafeyyu commented Dec 26, 2023

Environment

  • Server: dubbo java 3.2.9
  • Client: dubbo go 3.1.0
  • Protocol: dubbo
  • Registry: nacos

Issue description

go cliend调用java server的dubbo server,可以成功调用,但是go client接收到的时超时响应,设置了超时时间也无效,经调试,发现go client发送请求时,invocation的attachment里是设置了超时时间的,如下图
1
但是java server端的org.apache.dubbo.rpc.filter.ProfilerServerFilter类中的dumpIfNeed方法中,从invocation的attachement获取timeout的值是0,如下图
2

Logs

Click me to check logs
#服务端日志
2023-12-26T10:16:44.780�[0;39m �[2m[DubboServerHandler-10.6.8.106:20880-thread-56]�[0;39m �[35m16100�[0;39m �[33m WARN�[0;39m �[36mo.a.d.r.filter.ProfilerServerFilter�[0;39m �[2m:�[0;39m  [DUBBO] [Dubbo-Provider] execute service com.netpro.dubbo.dems.baseconfig.AlarmDubboService#add cost 160.479300 ms, this invocation almost (maybe already) timeout. Timeout: 0ms
client: 10.6.8.106:1947
invocation context:
path=com.netpro.dubbo.dems.baseconfig.AlarmDubboService;
async=false;
input=764;
environment=dev;
dubbo=2.0.2;
interface=com.netpro.dubbo.dems.baseconfig.AlarmDubboService;
version=;
timeout=0;
thread info: 
Start time: 1041345319061500
+-[ Offset: 0.000000ms; Usage: 160.479300ms, 100% ] Receive request. Server invoke begin.
  +-[ Offset: 0.248700ms; Usage: 160.072500ms, 99% ] Receive request. Server biz impl invoke begin., dubbo version: 3.2.9, current host: 10.6.8.106, error code: 3-7. This may be caused by , go to https://dubbo.apache.org/faq/3/7 to find instructions. 



#go客户端日志:
2023-12-26 10:46:06	WARN	proxy/proxy.go:212	[CallProxy] received rpc err: Failed to invoke the method add in the service com.netpro.dubbo.dems.baseconfig.AlarmDubboService. Tried 1 times of the providers [dubbo://:@10.6.8.106:20880/?interface=com.netpro.dubbo.dems.baseconfig.AlarmDubboService&group=&version= dubbo://:@10.6.8.106:20880/?interface=com.netpro.dubbo.dems.baseconfig.AlarmDubboService&group=&version=] (2/1)from the registry service-discovery-registry://10.5.0.15:8848?registry=nacos&registry.group=&registry.label=true&registry.namespace=dubboboot3&registry.preferred=false&registry.role=0&registry.timeout=5s&registry.ttl=15m&registry.weight=0&registry.zone=&remote-client-name=dubbo.registries-nacos-10.5.0.15%3A8848%2C10.5.0.16%3A8848%2C10.5.0.17%3A8848&simplified=false on the consumer 10.6.0.6 using the dubbo version 3.0.4. Last error is maybe the client read timeout or fail to decode tcp stream in Writer.Write.: maybe the client read timeout or fail to decode tcp stream in Writer.Write

@Jafeyyu
Copy link
Contributor Author

Jafeyyu commented Dec 26, 2023

进一步调试发现,在hessian.go中的marshalRequest方法中,对时间做了处理

func marshalRequest(encoder *hessian.Encoder, p DubboPackage) ([]byte, error) {
	service := p.Service
	request := EnsureRequestPayload(p.Body)
	_ = encoder.Encode(DEFAULT_DUBBO_PROTOCOL_VERSION)
	_ = encoder.Encode(service.Path)
	_ = encoder.Encode(service.Version)
	_ = encoder.Encode(service.Method)

	args, ok := request.Params.([]interface{})

	if !ok {
		logger.Infof("request args are: %+v", request.Params)
		return nil, perrors.Errorf("@params is not of type: []interface{}")
	}
	types, err := GetArgsTypeList(args)
	if err != nil {
		return nil, perrors.Wrapf(err, " PackRequest(args:%+v)", args)
	}
	_ = encoder.Encode(types)
	for _, v := range args {
		_ = encoder.Encode(v)
	}

	request.Attachments[PATH_KEY] = service.Path
	request.Attachments[VERSION_KEY] = service.Version
	if len(service.Group) > 0 {
		request.Attachments[GROUP_KEY] = service.Group
	}
	if len(service.Interface) > 0 {
		request.Attachments[INTERFACE_KEY] = service.Interface
	}
	if service.Timeout != 0 {
		request.Attachments[TIMEOUT_KEY] = strconv.Itoa(int(service.Timeout / time.Millisecond))
	}

	err = encoder.Encode(request.Attachments)
	return encoder.Buffer(), err
}

当timeout不等于0时,将timeout除以了time.Millisecond,但是在dubbo_invoker.go的getTimeout中,已经将时间处理成存入到attachment中

// get timeout including methodConfig
func (di *DubboInvoker) getTimeout(ivc *invocation.RPCInvocation) time.Duration {
	methodName := ivc.MethodName()
	if di.GetURL().GetParamBool(constant.GenericKey, false) {
		methodName = ivc.Arguments()[0].(string)
	}
	timeout := di.GetURL().GetParam(strings.Join([]string{constant.MethodKeys, methodName, constant.TimeoutKey}, "."), "")
	if len(timeout) != 0 {
		if t, err := time.ParseDuration(timeout); err == nil {
			// config timeout into attachment
			ivc.SetAttachment(constant.TimeoutKey, strconv.Itoa(int(t.Milliseconds()))) // 已经将timeout处理成毫秒存入attachment,应该将.Milliseconds()换成.Nanoseconds()
			return t
		}
	}
	// set timeout into invocation at method level
	ivc.SetAttachment(constant.TimeoutKey, strconv.Itoa(int(di.timeout.Milliseconds())))  // 已经将timeout处理成毫秒存入attachment,应该将.Milliseconds()换成.Nanoseconds()
	return di.timeout
}

最终导致timeout被缩小了1000000倍,变成了0,将上述方法中的两处Milliseconds()更改成Nanoseconds(),测试timeout获取正常

@DMwangnima
Copy link
Contributor

We would be appreciated if you could help to submit a PR to resolve this issue. If not, I would fix this bug.

@chickenlj chickenlj added waiting-for-feedback bug Something isn't working labels Dec 30, 2023
@chickenlj
Copy link
Contributor

Please remember to backport to the main branch once fixed.

Jafeyyu pushed a commit to Jafeyyu/dubbo-go that referenced this issue Dec 30, 2023
@Jafeyyu Jafeyyu mentioned this issue Dec 30, 2023
@Jafeyyu
Copy link
Contributor Author

Jafeyyu commented Dec 30, 2023

Please remember to backport to the main branch once fixed.

I have submit a PR, please check and verify, thanks

@DMwangnima
Copy link
Contributor

When analyzing the logic of DubboInvoker.getTimeout() and comparing it with dubbo's. We found another problem:

image

If users pass Reference.RequestTimeout directly, getTimeout could retrieve attachTimeout successfully, but it does not overwrite the value corresponding to constant.TimeoutKey with the parsed timeout value.

@chickenlj
Copy link
Contributor

If users pass Reference.RequestTimeout directly, getTimeout could retrieve attachTimeout successfully, but it does not overwrite the value corresponding to constant.TimeoutKey with the parsed timeout value.

Yeah, we need to move ivc.SetAttachment(constant.TimeoutKey, strconv.Itoa(int(timeout.Milliseconds()))) out of the else branch to make sure it always gets executed.

@chickenlj
Copy link
Contributor

最终导致timeout被缩小了1000000倍,变成了0,将上述方法中的两处Milliseconds()更改成Nanoseconds(),测试timeout获取正常

hessian最开始的实现中为什么要做 service.Timeout / time.Millisecond 那?是有什么特殊原因吗

@Jafeyyu
Copy link
Contributor Author

Jafeyyu commented Jan 3, 2024

最终导致timeout被缩小了1000000倍,变成了0,将上述方法中的两处Milliseconds()更改成Nanoseconds(),测试timeout获取正常

hessian最开始的实现中为什么要做 service.Timeout / time.Millisecond 那?是有什么特殊原因吗

我看了一下提交记录,dubbo_invoker.go从四年前添加getTimeout方法时就做了转换成millisecond的处理,而hession从3年前创建的时候就做了 service.Timeout / time.Millisecond 的处理,我个人感觉这个处理没有什么特殊原因,而是这两个地方没有协调好造成的。我当初选择更改dubbo_invoker.go中的getTimout处,是考虑在此处使用最基础的单位,然后其他地方可以按照各自的需求处理成想要的时间单位。但是如果决定要统一所有地方的时间单位,后续可以在dubbo_invoker的getTimeout方法中统一进行时间格式化,然后对hession进行变更,改为直接使用

FinalT pushed a commit to FinalT/dubbo-go that referenced this issue Jan 10, 2024
@drama10096
Copy link

这个问题,使用dubbo-go的3.0.5版本经常出现,有没有解决掉,在哪一个版本修复了呢??

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working waiting-for-feedback
Projects
None yet
Development

No branches or pull requests

4 participants