First Last Prev Next    This bug is not in your last search results.
Bug 6441 - multiple menustatus subscriptions can appear after repeated player changing
: multiple menustatus subscriptions can appear after repeated player changing
Status: CLOSED FIXED
Product: SB Controller
Classification: Unclassified
Component: Browser
: unspecified
: Macintosh Other
: -- normal (vote)
: 7.0.1
Assigned To: Andy Grundman
:
Depends on:
Blocks: 7459
  Show dependency tree / graph
 
Reported: 2007-12-21 14:56 UTC by Ben Klaas
Modified: 2008-05-08 12:52 UTC (History)
2 users (show)

See Also:
Category: ---

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Ben Klaas 2007-12-21 14:56:17 UTC 
When changing players, the proper behavior is Jive should unsubscribe to the previous player's menustatus subscription in SlimBrowser.free(), and subscribe to the new player in SlimBrowser.notify_playerCurrent(). What's happening, it appears, is that multiple menustatus subscriptions are open. This can get larger and larger over time.

_menuSink is the notification handler. Note how there are 2, then 3 log messages in this debug output after subsequent execution of changing players

Dec 21 12:14:47 (none) user.warn jive: (SelectPlayerApplet.lua:199) - Selected player is now Player {SoftSqueezee}
Dec 21 12:14:47 (none) user.warn jive: (AppletManager.lua:495) - storing settings at /usr/share/jive/applets/SlimDiscovery/settings.lua
Dec 21 12:14:47 (none) user.warn jive: (SetupFirmwareUpgradeMeta.lua:66) - PLAYER CURRENT!!
Dec 21 12:14:47 (none) user.warn jive: (SlimBrowserApplet.lua:1750) - ***** I AM UNSUBSCRIBING FROM /slim/menustatus/00:04:20:06:33:d0
Dec 21 12:14:47 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=50ms dequeue=14 in_queue=4
Dec 21 12:14:47 (none) user.warn jive: (SlimBrowserApplet.lua:1604) - I am now subscribing to /slim/menustatus/97:09:44:af:c6:36
Dec 21 12:14:47 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SelectPlayer)
Dec 21 12:14:47 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 97:09:44:af:c6:36
Dec 21 12:14:47 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SetupWallpaper)
Dec 21 12:14:47 (none) user.info jive: (AppletManager.lua:543) - Freeing nil
Dec 21 12:14:47 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=36ms dequeue=151 in_queue=1
Dec 21 12:14:47 (none) user.warn jive: (SqueezeboxJiveApplet.lua:263) - date=2007-12-21T12:14:48-06:00
Dec 21 12:14:47 (none) user.warn jive: (SqueezeboxJiveApplet.lua:264) - CCYY=2007 MM=12 DD=21 hh=12 mm=14 ss=48 TZ=-06:00
Dec 21 12:14:48 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=49ms dequeue=14 in_queue=1
Dec 21 12:14:48 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:14:48 (none) user.warn jive: (NetworkThread.lua:336) - NetworkThread pump=1049ms out_queueH=4 out_queueL=0
Dec 21 12:14:50 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:14:50 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:14:50 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 97:09:44:af:c6:36
Dec 21 12:14:51 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 00:04:20:06:33:d0
Dec 21 12:14:52 (none) user.warn jive: (SelectPlayerApplet.lua:199) - Selected player is now Player {Office SB3}
Dec 21 12:14:52 (none) user.warn jive: (AppletManager.lua:495) - storing settings at /usr/share/jive/applets/SlimDiscovery/settings.lua
Dec 21 12:14:52 (none) user.warn jive: (SetupFirmwareUpgradeMeta.lua:66) - PLAYER CURRENT!!
Dec 21 12:14:52 (none) user.warn jive: (SlimBrowserApplet.lua:1750) - ***** I AM UNSUBSCRIBING FROM /slim/menustatus/97:09:44:af:c6:36
Dec 21 12:14:52 (none) user.warn jive: (SlimBrowserApplet.lua:1604) - I am now subscribing to /slim/menustatus/00:04:20:06:33:d0
Dec 21 12:14:52 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SelectPlayer)
Dec 21 12:14:52 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 00:04:20:06:33:d0
Dec 21 12:14:52 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SetupWallpaper)
Dec 21 12:14:52 (none) user.info jive: (AppletManager.lua:543) - Freeing nil
Dec 21 12:14:53 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=122ms dequeue=200 in_queue=6
Dec 21 12:14:53 (none) user.warn jive: (SqueezeboxJiveApplet.lua:263) - date=2007-12-21T12:14:54-06:00
Dec 21 12:14:53 (none) user.warn jive: (SqueezeboxJiveApplet.lua:264) - CCYY=2007 MM=12 DD=21 hh=12 mm=14 ss=54 TZ=-06:00
Dec 21 12:14:53 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=3ms dequeue=53 in_queue=0
Dec 21 12:14:54 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:14:54 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=75ms dequeue=14 in_queue=1
Dec 21 12:14:54 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:14:54 (none) user.warn jive: (NetworkThread.lua:336) - NetworkThread pump=1263ms out_queueH=1 out_queueL=0
Dec 21 12:14:59 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:14:59 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:14:59 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=126ms dequeue=3 in_queue=1
Dec 21 12:14:59 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 00:04:20:06:33:d0
Dec 21 12:15:00 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 97:09:44:af:c6:36
Dec 21 12:15:01 (none) user.warn jive: (SelectPlayerApplet.lua:199) - Selected player is now Player {SoftSqueezee}
Dec 21 12:15:01 (none) user.warn jive: (AppletManager.lua:495) - storing settings at /usr/share/jive/applets/SlimDiscovery/settings.lua
Dec 21 12:15:01 (none) user.warn jive: (SetupFirmwareUpgradeMeta.lua:66) - PLAYER CURRENT!!
Dec 21 12:15:01 (none) user.warn jive: (SlimBrowserApplet.lua:1750) - ***** I AM UNSUBSCRIBING FROM /slim/menustatus/00:04:20:06:33:d0
Dec 21 12:15:01 (none) user.warn jive: (SlimBrowserApplet.lua:1604) - I am now subscribing to /slim/menustatus/97:09:44:af:c6:36
Dec 21 12:15:01 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=90ms dequeue=13 in_queue=4
Dec 21 12:15:01 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SelectPlayer)
Dec 21 12:15:01 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 97:09:44:af:c6:36
Dec 21 12:15:01 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SetupWallpaper)
Dec 21 12:15:01 (none) user.info jive: (AppletManager.lua:543) - Freeing nil
Dec 21 12:15:01 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=106ms dequeue=196 in_queue=2
Dec 21 12:15:01 (none) user.warn jive: (SqueezeboxJiveApplet.lua:263) - date=2007-12-21T12:15:03-06:00
Dec 21 12:15:01 (none) user.warn jive: (SqueezeboxJiveApplet.lua:264) - CCYY=2007 MM=12 DD=21 hh=12 mm=15 ss=03 TZ=-06:00
Dec 21 12:15:03 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:15:03 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:15:03 (none) user.warn jive: (NetworkThread.lua:336) - NetworkThread pump=1322ms out_queueH=3 out_queueL=0
Dec 21 12:15:06 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:15:06 (none) user.warn jive: (SelectPlayerApplet.lua:113) - _addPlayerItem
Dec 21 12:15:06 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 97:09:44:af:c6:36
Dec 21 12:15:07 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 00:04:20:06:33:d0
Dec 21 12:15:08 (none) user.warn jive: (SelectPlayerApplet.lua:199) - Selected player is now Player {Office SB3}
Dec 21 12:15:08 (none) user.warn jive: (AppletManager.lua:495) - storing settings at /usr/share/jive/applets/SlimDiscovery/settings.lua
Dec 21 12:15:08 (none) user.warn jive: (SetupFirmwareUpgradeMeta.lua:66) - PLAYER CURRENT!!
Dec 21 12:15:08 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=56ms dequeue=16 in_queue=2
Dec 21 12:15:08 (none) user.warn jive: (SlimBrowserApplet.lua:1750) - ***** I AM UNSUBSCRIBING FROM /slim/menustatus/97:09:44:af:c6:36
Dec 21 12:15:08 (none) user.warn jive: (SlimBrowserApplet.lua:1604) - I am now subscribing to /slim/menustatus/00:04:20:06:33:d0
Dec 21 12:15:08 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=126ms dequeue=4 in_queue=5
Dec 21 12:15:08 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SelectPlayer)
Dec 21 12:15:08 (none) user.info jive: (SelectPlayerApplet.lua:135) - previewing background wallpaper for 00:04:20:06:33:d0
Dec 21 12:15:08 (none) user.warn jive: (AppletManager.lua:522) - AppletManager:_freeApplet(SetupWallpaper)
Dec 21 12:15:08 (none) user.info jive: (AppletManager.lua:543) - Freeing nil
Dec 21 12:15:08 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=69ms dequeue=68 in_queue=1
Dec 21 12:15:09 (none) user.warn jive: (SqueezeboxJiveApplet.lua:263) - date=2007-12-21T12:15:09-06:00
Dec 21 12:15:09 (none) user.warn jive: (SqueezeboxJiveApplet.lua:264) - CCYY=2007 MM=12 DD=21 hh=12 mm=15 ss=09 TZ=-06:00
Dec 21 12:15:09 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:15:09 (none) user.warn jive: (NetworkThread.lua:240) - NetworkThread select=49ms dequeue=13 in_queue=1
Dec 21 12:15:09 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:15:09 (none) user.warn jive: (SlimBrowserApplet.lua:684) - *********** YOU ARE IN _menuSink***********
Dec 21 12:15:09 (none) user.warn jive: (NetworkThread.lua:336) - NetworkThread pump=1430ms out_queueH=4 out_queueL=0
Dec 21 12:15:20 (none) user.warn jive: (SqueezeboxJiveApplet.lua:524) - setPowerState=dimmed acpower=false
Dec 21 12:15:20 (none) user.warn jive: (SqueezeboxJiveApplet.lua:594) - interval=60000
Comment 1 Richard Titmuss 2008-03-12 04:53:31 UTC 
Reset priority
Comment 2 Ben Klaas 2008-03-19 08:30:50 UTC 
removing priorities from all 7.0.1 target bugs for re-prioritizing
Comment 3 Ben Klaas 2008-03-24 14:39:00 UTC 
this is still easily reproducible in SC trunk and Squeezeplay trunk when going back and forth between players:

163147:23035 WARN (SlimBrowserApplet.lua:882) - _menuSink(Office SB3)
163147:23037 INFO (SlimBrowserApplet.lua:653) - _connectingToPlayer popup hide
163147:23040 WARN (SlimBrowserApplet.lua:882) - _menuSink(Office SB3)
163147:23042 WARN (SlimBrowserApplet.lua:882) - _menuSink(Office SB3)
163147:23044 WARN (SlimBrowserApplet.lua:882) - _menuSink(Office SB3)

_menuSink() is the menustatus subscription response handler. There should only be one _menuSink() call after switching back to this player. It seems to increment by one most but not all of the time when a player comes back onStage.

Comet debug on the SC side is showing multiple notifications being sent back to Squeezeplay in these situations.

There are two other player-based subscriptions, playerstatus and displaystatus. These do not seem to pile up like menustatus notifications do. menustatus differs in that issues notifications via notifyFromArray().

I'm a bit stuck in figuring out where the breadcrumbs lead from here...
Comment 4 Ben Klaas 2008-03-31 08:31:49 UTC 
put some debug on the SC side when this is recreated.

on the jive side, I show 5 calls to _menuSink() after this particular connect-to-player:
102828:52459 INFO (SlimBrowserApplet.lua:809) - _menuSink()
102828:52461 INFO (SlimBrowserApplet.lua:580) - _connectingToPlayer popup hide
102828:52463 INFO (SlimBrowserApplet.lua:809) - _menuSink()
102828:52469 INFO (SlimBrowserApplet.lua:809) - _menuSink()
102828:52478 INFO (SlimBrowserApplet.lua:809) - _menuSink()
102828:52482 INFO (SlimBrowserApplet.lua:809) - _menuSink()

but on the SC side, only one notification is showing up on the console:
[10:28:27.7772] Slim::Control::Jive::_notifyJive (914) Jive notification: 00:04:20:06:33:d0
[10:28:28.2733] Slim::Control::Jive::menuNotification (1724) Menustatus notification sent.

So perhaps this issue is 100% on the Jive side and doesn't actually represent a proliferation of comet subscriptions?
Comment 5 Ben Klaas 2008-04-15 12:22:55 UTC 
DEBUG DUMP OF self.subs in jive.net.Comet.unsubscribe issue is reproduced:

{ --[[table: 0x162ab670]]
  { --[[table: 0x162aedb0]]
    func = function: 0x11f3290,
    request = { --[[table: 0x162ae7b0]]
      "serverstatus",
      0,
      50,
      "subscribe:60",
    },
    subscription = "/slim/serverstatus",
    reqid = 1,
  },
}

So, the only thing in the table after an unsubscribe event (change player) is serverstatus. Yet there are three _menuSink() calls in the output below this dump:

140626:35742 INFO (SlimBrowserApplet.lua:2094) - Subscribing to /slim/menustatus/00:04:20:16:1a:26
140626:35744 INFO (SlimBrowserApplet.lua:2133) - power: 1
140626:35744 INFO (SlimBrowserApplet.lua:493) - _connectingToPlayer popup show
140626:35744 INFO (SetupWallpaperApplet.lua:99) - SetupWallpaper:notify_playerCurrent(Player {Squeezebox 6})
140626:35745 INFO (SetupWallpaperApplet.lua:363) - SetupWallpaper, setting wallpaper for 00:04:20:16:1a:26
140626:35745 INFO (SelectPlayerApplet.lua:267) - previewing background wallpaper for 00:04:20:16:1a:26
140626:35745 INFO (AppletManager.lua:566) - Freeing: SetupWallpaper
140626:35948 INFO (SlimBrowserApplet.lua:809) - _menuSink()
140626:35949 WARN (SlimBrowserApplet.lua:810) - stack traceback:
        ...play/share/applets/SlimBrowser/SlimBrowserApplet.lua:810: in function 'func'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:848: in function '_response'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:726: in function <...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:717>
140626:35951 INFO (SlimBrowserApplet.lua:580) - _connectingToPlayer popup hide
140626:35959 INFO (SlimBrowserApplet.lua:809) - _menuSink()
140626:35960 WARN (SlimBrowserApplet.lua:810) - stack traceback:
        ...play/share/applets/SlimBrowser/SlimBrowserApplet.lua:810: in function 'func'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:848: in function '_response'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:726: in function <...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:717>
140626:35962 INFO (SlimBrowserApplet.lua:809) - _menuSink()
140626:35962 WARN (SlimBrowserApplet.lua:810) - stack traceback:
        ...play/share/applets/SlimBrowser/SlimBrowserApplet.lua:810: in function 'func'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:848: in function '_response'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:726: in function <...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:717>
140626:35965 INFO (SlimBrowserApplet.lua:809) - _menuSink()
140626:35965 WARN (SlimBrowserApplet.lua:810) - stack traceback:
        ...play/share/applets/SlimBrowser/SlimBrowserApplet.lua:810: in function 'func'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:848: in function '_response'
        ...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:726: in function <...squeezeplay/src/squeezeplay/share/jive/net/Comet.lua:717>

SC only registers one notification being sent out.

I'm at a loss for where to go next with this. Any thoughts Richard/Andy?
Comment 6 Richard Titmuss 2008-04-17 08:02:25 UTC 
Fixed Comet unsubscriptions in Jive in 7.0.1 r2267. This still does not seem to be working correctly, Andy will look at the SC side.
Comment 7 Andy Grundman 2008-04-18 07:06:36 UTC 
Fixed in change 18853.
Comment 8 James Richardson 2008-05-08 12:52:17 UTC 
(In reply to comment #7)
> Fixed in change 18853.
> 

closing bug
First Last Prev Next    This bug is not in your last search results.