Bug 13094 - SN Request connection's timeout behavior is poor, causes frequent ~3 second full Spinny
: SN Request connection's timeout behavior is poor, causes frequent ~3 second f...
Status: CLOSED FIXED
Product: SqueezePlay
Classification: Unclassified
Component: Networking
: unspecified
: PC Other
: P1 normal (vote)
: 7.4.0
Assigned To: Richard Titmuss
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2009-07-28 09:00 UTC by Wadzinski Tom
Modified: 2009-10-05 14:26 UTC (History)
1 user (show)

See Also:
Category: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Wadzinski Tom 2009-07-28 09:00:07 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): ?
Comment 1 Wadzinski Tom 2009-07-28 09:19:21 UTC
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)
Comment 2 SVN Bot 2009-09-02 14:28:33 UTC
 == 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.
Comment 3 James Richardson 2009-10-05 14:26:42 UTC
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.