Bug #1855

Sometimes green notification popups are staying too long

Added by Leonid Protasov over 7 years ago. Updated about 7 years ago.

Status:FixedStart date:01/13/2014
Priority:HighDue date:
Assignee:Andreas Smas% Done:

100%

Category:User interface
Target version:4.6
Found in version:4.5.100 Platform:Linux

Description

That happens when plugin autoupdate notification is shown at the same time when notification about new ST version is show too I beleive.

Found on PS3/RPI.

Associated revisions

Revision c0efdbd9
Added by Andreas Smas about 7 years ago

Add debug switch (in settings:dev) to enable timer debugging

refs #1855

Change included in version 4.5.57

Revision f85552ad
Added by Andreas Smas about 7 years ago

Log slow callouts

refs #1855

Change included in version 4.5.104

Revision cda0e974
Added by Andreas Smas about 7 years ago

Set timeouts on UPnP notification requests

Fixes #1855

Change included in version 4.5.120

History

#1 Updated by Leonid Protasov about 7 years ago

  • Subject changed from Plugin is updated to bla bla bla ver notification is sometimes staying to long to "Plugin X is updated to Y version: notification is sometimes staying to long

Did more tests and looks like those two events are not connected. Green popup just stays to long sometimes. Still don't know why but it happens from time to time.

#2 Updated by Leonid Protasov about 7 years ago

  • Subject changed from "Plugin X is updated to Y version: notification is sometimes staying to long to Sometimes green notification popups are staying too long
  • Priority changed from High to Normal

#3 Updated by Leonid Protasov about 7 years ago

Today hdrezka plugin was autoupdated to 1.3 and st notificated about 4.3.725. Message with plugin update stayed unusually long... That is interesting that i added some bookmark on homescreen and notification about adding bookmark stayed long too...

#4 Updated by Leonid Protasov about 7 years ago

From time to time I catch that bug even if there is no updates at all. When adding bookmarks. Looks like notify messages need more debug loggin as now it just logs single notify event...

Platforms I seen it on: RPi/PS3.

#5 Updated by Andreas Smas about 7 years ago

  • Status changed from New to Accepted
  • Target version deleted (4.4)

I can't reproduce this. But I agree that it happens now and then. It will be a known issue for 4.4

#6 Updated by Leonid Protasov about 7 years ago

I catch it if you coldstart ST and it detects new ST ver on server and some plugin is autoupdated to new version. That way green notification of plugin is updated stays too long... Seen that on PS3 last time (ST updated to 4.4 and HDSerials to new ver).

#7 Updated by Leonid Protasov about 7 years ago

  • Priority changed from Normal to High
  • Target version set to 4.6

Looks like finally I managed to reproduce it all time on ALL PLATFORMS:
1. Install rad.io plugin from my repo
2. Open it and go into "Most wanted"
3. Don't wait it finish loading and start playing any station
4. Restart ST
5. Go into Settings->Clear cache and notification message will stay very long

After steps above - you can close ST, run again, go directly into settings->clear cache and and it stays long...

#8 Updated by Leonid Protasov about 7 years ago

Alternatively instead Clear cache you can use Clear metadata - result will be the same - notification will stay too long...

#9 Updated by Leonid Protasov about 7 years ago

  • Status changed from Accepted to Fixed
  • % Done changed from 0 to 100

Can't produce anymore. Looks like it's fixed in 4.5.57.

#10 Updated by Leonid Protasov about 7 years ago

The bug is still there. But this time I switched debug timers so I'll keep an eye on that...

#11 Updated by Leonid Protasov about 7 years ago

  • Found in version changed from All to 4.5.100
  • Platform changed from RPi to Linux

Please reopen this. I got it on Linux:

Full log: http://sprunge.us/SEfF

Part of the log.

00:00:36.625: navigator [INFO]:Opening search:settings:dev
00:00:36.629: thread [DEBUG]:Thread jsmodel exited
00:00:50.632: navigator [INFO]:Opening smb://192.168.0.190/c$
00:00:50.633: thread [DEBUG]:Created detached thread: fa_open
00:00:54.009: navigator [INFO]:Opening smb://192.168.0.190/c$/hunter
00:00:54.010: thread [DEBUG]:Created detached thread: fa_open
00:00:54.034: DB [DEBUG]:Opened database /root/.hts/showtime/metadb/meta.db pages: free=1 total=195
00:01:00.570: notify [INFO]:Добавлены новые закладки: hunter
00:01:34.738: Callout [DEBUG]:0x613470,0x7f7cdc023040 took 30030489 us
00:01:34.745: Callout [DEBUG]:0x52ca40,0x1fbf500 took 6982 us
00:01:34.747: Callout [DEBUG]:0x553740,0x7f7ce0000920 took 1744 us
00:01:41.316: Settings [DEBUG]:Wrote 279 bytes to "/root/.hts/showtime/settings/bookmarks2" 
00:01:41.320: Settings [DEBUG]:Wrote 21 bytes to "/root/.hts/showtime/settings/dev" 
00:01:41.320: Callout [DEBUG]:0x567300,(nil) took 10329 us
00:01:41.328: Callout [DEBUG]:0x52ca40,0x1fbf500 took 7843 us
00:01:42.367: Callout [DEBUG]:0x52ca40,0x1fbf500 took 22636 us
00:01:43.382: Callout [DEBUG]:0x52ca40,0x1fbf500 took 11895 us
00:01:43.387: Callout [DEBUG]:0x5254e0,(nil) took 5323 us
00:01:44.391: Callout [DEBUG]:0x52ca40,0x1fbf500 took 1536 us
00:01:45.401: Callout [DEBUG]:0x52ca40,0x1fbf500 took 7360 us
00:01:46.424: Callout [DEBUG]:0x52ca40,0x1fbf500 took 21021 us
00:01:47.431: Callout [DEBUG]:0x52ca40,0x1fbf500 took 2132 us
00:01:48.450: Callout [DEBUG]:0x52ca40,0x1fbf500 took 16986 us
00:01:49.472: Callout [DEBUG]:0x52ca40,0x1fbf500 took 20292 us
00:01:50.480: Callout [DEBUG]:0x52ca40,0x1fbf500 took 4961 us
00:01:51.500: Callout [DEBUG]:0x52ca40,0x1fbf500 took 16872 us
00:01:52.639: Callout [DEBUG]:0x52ca40,0x1fbf500 took 13761 us
00:01:53.662: Callout [DEBUG]:0x52ca40,0x1fbf500 took 19693 us
00:01:54.668: Callout [DEBUG]:0x52ca40,0x1fbf500 took 4292 us
00:01:55.677: Callout [DEBUG]:0x52ca40,0x1fbf500 took 6267 us
00:01:56.700: Callout [DEBUG]:0x52ca40,0x1fbf500 took 20733 us

#12 Updated by Andreas Smas about 7 years ago

  • Status changed from Fixed to Accepted

#13 Updated by Andreas Smas about 7 years ago

00:01:34.738: Callout [DEBUG]:0x613470,0x7f7cdc023040 took 30030489 us

That's the source of this evilness.

#14 Updated by Andreas Smas about 7 years ago

  • Priority changed from High to Normal

#15 Updated by Leonid Protasov about 7 years ago

00:00:04.073: Callout [DEBUG]:/var/tmp/buildagent/repos/showtime/src/htsmsg/htsmsg_store.c:279 executed for 1323476us

From: http://sprunge.us/IPEE

#16 Updated by Leonid Protasov about 7 years ago

  • Priority changed from Normal to High

And the winner is:

00:22:47.839: Callout [DEBUG]:/var/tmp/buildagent/repos/showtime/src/upnp/upnp_event.c:154 executed for 30097052us
00:23:18.144: Callout [DEBUG]:/var/tmp/buildagent/repos/showtime/src/upnp/upnp_event.c:337 executed for 30302355us
00:23:48.262: Callout [DEBUG]:/var/tmp/buildagent/repos/showtime/src/upnp/upnp_event.c:337 executed for 30119399us

Log with this and crash on RPI - while i was playing icecast i tried to open smb share - st crashed (see log) http://sprunge.us/OUUG

#17 Updated by Andreas Smas about 7 years ago

Got it. Great work. Not sure what the crash is about though. Probably unrelated

#18 Updated by Leonid Protasov about 7 years ago

I beleive the crash is related to https://showtimemediacenter.com/issues/1970

#19 Updated by Andreas Smas about 7 years ago

  • Status changed from Accepted to Fixed

Applied in changeset git|commit:cda0e974d4f024aa433117146b100a8e1cc37e01.

Also available in: Atom PDF