Bug 8710 - Race condition in slim_tcpdata_stop / decode_stop
: Race condition in slim_tcpdata_stop / decode_stop
Status: CLOSED FIXED
Product: SB 2/3
Classification: Unclassified
Component: Misc
: 100
: PC Other
: P1 normal (vote)
: 7.3
Assigned To: Andy Grundman
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-07-11 20:20 UTC by Andy Grundman
Modified: 2008-12-15 12:05 UTC (History)
4 users (show)

See Also:
Category: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Andy Grundman 2008-07-11 20:20:29 UTC
To reproduce:

Seek near the end of a track using the web UI.
Wait for the next track to start.
Sometimes a track start event won't be sent.

I think I tracked this down to slim_tcpdata_stop vs. decode_stop.  When the bug occurs, decode_stop is not handled until after the next track has already started.  Should slim_tcpdata_stop wait until decode_stop is handled before returning?

0: 01634.534: Info: slim_tcpdata.c[750]: STRM control frame came in, command: q
0: 01634.535: Trace: slim_tcpdata.c[676]: slim_tcpdata_stop: num_tracks_started = 0
0: 01634.535: Info: slim_tcpdata.c[164]: event: f
0: 01634.537: Info: slim_tcpdata.c[750]: STRM control frame came in, command: s
0: 01634.537: Info: slim_tcpdata.c[786]: len request_string: 00000034
0: 01634.538: Info: slim_tcpdata.c[793]: req: GET /stream.mp3?player=00:04:20:06:ad:91 HTTP/1.0
0: 01634.538: 
0: 01634.538: 
0: 01634.538: 
0: 01634.538: Trace: slim_tcpdata.c[795]: FLAGS 0
0: 01634.539: Info: decode.c[509]: decode_start
0: 01634.539: Info: slim_tcpdata.c[164]: event: f
0: 01634.540: Info: slim_tcpdata.c[693]: data connect: 0.0.0.0:9000
0: 01634.540: Info: slim_tcpdata.c[164]: event: c
0: 01634.542: Info: slim_tcpdata.c[310]: Sending track started event
0: 01634.542: Info: slim_tcpdata.c[164]: event: s
1: 01634.542: Info: decode.c[762]: Decode thread: handling message
1: 01634.543: Info: decode.c[162]: decode_stop
0: 01634.543: Trace: slim_tcpdata.c[313]: num_tracks_started = 2
1: 01634.543: Trace: decode.c[169]: decode_tracks = 0
Comment 1 Alan Young 2008-07-12 00:52:50 UTC
This explains a couple of issues.
Comment 2 Chris Owens 2008-07-14 10:10:11 UTC
Andy notes that he needs Richard or Sean to help figure out the proper way to resolve this race condition.

Comment 3 Sean Adams 2008-07-14 10:26:38 UTC
If decode_stop occurs in the background (in the decode thread) and is known to always complete in a small amount of time (<10ms) then it would be OK to block mainline execution until it completes. 

Other solutions could get a lot more complicated - would involve either queuing the commands somehow, or making SC wait for one operation to complete before sending the next.
Comment 4 Andy Grundman 2008-07-14 21:34:32 UTC
Is a busy loop like this OK?  Maybe it should only wait for a certain amount of time, then just return?

--- net/slim_tcpdata.c	(revision 41103)
+++ net/slim_tcpdata.c	(local)
@@ -675,6 +675,8 @@
 #ifdef UPLOAD_TEST
 	upload_stop();
 #endif
+	/* Bug 8710, wait until the decode thread is stopped */
+	while ( decode_decoder_state() != 0 ) {}
Comment 5 Sean Adams 2008-07-14 21:37:55 UTC
I think so - try it. Yes it should give up (and DEBUG_PRINTF a warning) after 100ms.
Comment 6 Andy Grundman 2008-11-03 11:09:39 UTC
Fixed in r5094.
Comment 7 James Richardson 2008-12-15 12:05:17 UTC
This bug has been fixed in the 7.3.0 release version of SqueezeCenter!

Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already.  

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.