Bugzilla – Bug 13094
SN Request connection's timeout behavior is poor, causes frequent ~3 second full Spinny
Last modified: 2009-10-05 14:26:42 UTC
After 70 seconds the rhttp connection times out, which is by design (the chttp conneciton is kept alive by serverstatus). When a new request occurs, the following happens: 1) handleAdvice is called from getRequestSink on the timeout error. 2) serverDisconnected notification is sent which causes slimBrowse to put up the spinny. 3) a reconnect happens after a 3 second timeout I notice that after a much longer time the timeout doesn't happen. Perhaps that's because the connection is fully closed and the following never occurs: if type(v) == "userdata" and t.timeout > 0 and now - t.lastSeen > t.timeout then log:error("network thread timeout for ", t.task) t.task:addTask("inactivity timeout") end I'll investigate that a bit more. Dump: 20090728 15:53:11.873 DEBUG applet.SlimBrowser - SlimBrowserApplet.lua:623 _performJSONAction(from:0, qty:200): 20090728 15:53:11.873 DEBUG net.comet - Comet.lua:459 Comet {mysqueezebox.com}: request(function: 0x1747a5a0, reqid:13, 00:1e:c2:1e:0d:e1, amazon,items,0,200,menu:amazon,useContextMenu:1, priority:nil) 20090728 15:53:11.873 DEBUG net.comet - Comet.lua:355 Sending pending request(s): { --[[table: 0x1747ab80]] { --[[table: 0x1747ac00]] id = 13, data = { --[[table: 0x1747ac60]] request = { --[[table: 0x1747abc0]] "00:1e:c2:1e:0d:e1", { --[[table: 0x174c4320]] "amazon", "items", 0, 200, "menu:amazon", "useContextMenu:1", }, }, response = "/220213Xcffcc56a7f654cbe078d5bc5bed9898fX1248796353Xf03f157d/slim/request", }, channel = "/slim/request", }, } 20090728 15:53:11.897 ERROR net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Request}(R)) stack traceback: ...lay/src/squeezeplay/share/jive/net/NetworkThread.lua:146: in function '_timeout' ...lay/src/squeezeplay/share/jive/net/NetworkThread.lua:187: in function <...lay/src/squeezeplay/share/jive/net/NetworkThread.lua:155> [C 0x5d1c4]: in function 'pcall' ...lay/src/squeezeplay/share/jive/net/NetworkThread.lua:205: in function <...lay/src/squeezeplay/share/jive/net/NetworkThread.lua:194> 20090728 15:53:11.902 ERROR net.http - SocketHttp.lua:486 SocketHttp {mysqueezebox.com_Request}:t_rcvHeaders.pump:inactivity timeout stack traceback: ...zeplay/src/squeezeplay/share/jive/net/SocketHttp.lua:486: in function 'pump' ...ezeplay/src/squeezeplay/share/jive/net/SocketTcp.lua:192: in function 'readPump' ...queezeplay/src/squeezeplay/share/jive/net/Socket.lua:161: in function <...queezeplay/src/squeezeplay/share/jive/net/Socket.lua:159> 20090728 15:53:11.902 INFO net.comet - Comet.lua:818 Comet {mysqueezebox.com}: _getRequestSink error: inactivity timeout 20090728 15:53:11.902 INFO net.comet - Comet.lua:998 Comet {mysqueezebox.com}: handleAdvice state=CONNECTED 20090728 15:53:11.902 DEBUG net.comet - Comet.lua:547 Comet {mysqueezebox.com}: state is UNCONNECTED 20090728 15:53:11.902 INFO squeezebox.server - SlimServer.lua:669 disconnected mysqueezebox.com idleTimeoutTriggered: nil 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:198 Comet {basementtv}: connect state=UNCONNECTED 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:568 Comet {basementtv}: _handshake(), calling: http://192.168.1.103:9000/cometd 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/serverstatus 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/firmwarestatus 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:547 Comet {basementtv}: state is CONNECTING 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:198 Comet {Tom Wadzinski’s MacBook Pro}: connect state=UNCONNECTED 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:568 Comet {Tom Wadzinski’s MacBook Pro}: _handshake(), calling: http://192.168.1.106:9000/cometd 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/serverstatus 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/firmwarestatus 20090728 15:53:11.903 DEBUG net.comet - Comet.lua:547 Comet {Tom Wadzinski’s MacBook Pro}: state is CONNECTING 20090728 15:53:11.904 DEBUG net.comet - Comet.lua:198 Comet {Kitchen-Netbook}: connect state=UNCONNECTED 20090728 15:53:11.904 DEBUG net.comet - Comet.lua:568 Comet {Kitchen-Netbook}: _handshake(), calling: http://192.168.1.149:9000/cometd 20090728 15:53:11.904 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/serverstatus 20090728 15:53:11.904 DEBUG net.comet - Comet.lua:580 Will re-subscribe to /slim/firmwarestatus 20090728 15:53:11.904 DEBUG net.comet - Comet.lua:547 Comet {Kitchen-Netbook}: state is CONNECTING 20090728 15:53:11.904 INFO applet.SlimBrowser - SlimBrowserApplet.lua:2498 _problemConnectingPopup 20090728 15:53:11.906 ERROR net.comet - Comet.lua:1039 Comet {mysqueezebox.com}: advice is retry, connect in 3.163 seconds stack traceback: ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:1039: in function <...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:997> (tail call): ?
I found that after about 85 seconds, the connection is removed, such that the next request get a new connection smoothly. So it seems that the timeout code is problematic, but only gets used in the short time period where the internal timeout is past but the connection has not been removed (due to actual disconnect, I presume)
== Auto-comment from SVN commit #7388 to the jive repo by richard == == https://svn.slimdevices.com/jive?view=revision&revision=7388 == Fixed bug #13094 When idle the http socket was not honoring it's timeout. This could create problems for the Comet request connection, between the idle timeout and the actual disconnection.
This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server! * SqueezeCenter: 28672 * Squeezebox 2 and 3: 130 * Transporter: 80 * Receiver: 65 * Boom: 50 * Controller: 7790 * Radio: 7790 Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.