1062487 - Loop server ringing timeout is incorrect

Status: VERIFIED DUPLICATE of bug 1062266

(Hello (Loop) :: Server, defect)

Description

[Mark Banner (:standard8)]

Testing with https://loop-dev.stage.mozaws.net or with the server running locally, I'm seeing a timeout of about 8 seconds from "alerting" to "timeout".

According to the spec and the default in the configuration it is meant to be about 30 seconds.

Comment 1

[Mark Banner (:standard8)]

I did a bit of debug and the output is below.

There seems to be some nasty interaction between the redis ttl for call states, and the manually implemented timeouts.

In the log below:

- "Timeout1" is the initial connection timeout where both clients should be connected within 10 seconds.
- "Timeout2" is the ringing timeout of 30 seconds.

Although the log has only bits, the ttl is first 30 seconds (ringing timeout?), then 10 seconds (connection timeout?), by the time the caller connects, its down to 9.9 s, by the time the callee connects, its down to 7.5 seconds.

"Timeout1" fires, finds that the record is no longer into redis (due to the ttl having expired), and therefore assumes it is terminated, and sends out the terminate result.

This is therefore ~ 20 seconds too early, as it wasn't meant to be sent out until "Timeout2" is triggered.




info:  op=request.summary, code=200, path=/calls/sf4oN4Z3KLc, method=get, , agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.8; rv:35.0) Gecko/20100101 Firefox/35.0, time=2014-09-04T09:34:31Z, uid=undefined, callId=undefined, token=sf4oN4Z3KLc, v=0.11.0-DEV, name=mozilla-loop-server, hostname=Mark-Banners-MacBook-Pro.local, lang=en-US,en;q=0.5, ip=127.0.0.1, errno=0
setCallState e82b25a8a9f1a5d42b73f45177bc77bc init
setCallState e82b25a8a9f1a5d42b73f45177bc77bc init
ttl 30
setCallState e82b25a8a9f1a5d42b73f45177bc77bc init
ttl 10
info:  op=request.summary, code=200, path=/calls/sf4oN4Z3KLc, method=post, , agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.8; rv:35.0) Gecko/20100101 Firefox/35.0, time=2014-09-04T09:34:33Z, uid=undefined, callId=e82b25a8a9f1a5d42b73f45177bc77bc, token=sf4oN4Z3KLc, v=0.11.0-DEV, name=mozilla-loop-server, hostname=Mark-Banners-MacBook-Pro.local, lang=en-US,en;q=0.5, ip=127.0.0.1, errno=0
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
helloState init
setCallState e82b25a8a9f1a5d42b73f45177bc77bc init.caller
ttl 9.912
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
info:  op=request.summary, code=200, path=/calls, method=get, version=1409823273352, agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10.8; rv:35.0) Gecko/20100101 Firefox/35.0, time=2014-09-04T09:34:35Z, uid=952ccd77c40097bb6110722e6d709b5f12eb86544276d24ed7b29750e9caccd9, callId=undefined, token=undefined, v=0.11.0-DEV, name=mozilla-loop-server, hostname=Mark-Banners-MacBook-Pro.local, lang=en-US, en, ip=127.0.0.1, errno=0
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
helloState init
setCallState e82b25a8a9f1a5d42b73f45177bc77bc init.callee
ttl 7.47
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
Timeout1
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
Timeout1 state alerting
Timeout1
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
Falling back
get call returns Terminated!
Timeout1 state terminated
timeout1 broadcast
setCallState e82b25a8a9f1a5d42b73f45177bc77bc terminated
ttl undefined
setCallState e82b25a8a9f1a5d42b73f45177bc77bc terminated
ttl 20
terminated!
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
Falling back
get call returns Terminated!
Timeout2
getCallState e82b25a8a9f1a5d42b73f45177bc77bc
Falling back
get call callback null!
Timeout2 state null

Comment 2

[Rémy Hubscher (:natim)]

Will be fixed by Bug 1062266

Comment 3

[James Bonacci [:jbonacci]]

ok