{"action":"created","issue":{"url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/772","repository_url":"https://api.github.com/repos/mikebrady/shairport-sync","labels_url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/772/labels{/name}","comments_url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/772/comments","events_url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/772/events","html_url":"https://github.com/mikebrady/shairport-sync/issues/772","id":379686933,"node_id":"MDU6SXNzdWUzNzk2ODY5MzM=","number":772,"title":"tuneblade connection issues.","user":{"login":"gibman","id":1027462,"node_id":"MDQ6VXNlcjEwMjc0NjI=","avatar_url":"https://avatars2.githubusercontent.com/u/1027462?v=4","gravatar_id":"","url":"https://api.github.com/users/gibman","html_url":"https://github.com/gibman","followers_url":"https://api.github.com/users/gibman/followers","following_url":"https://api.github.com/users/gibman/following{/other_user}","gists_url":"https://api.github.com/users/gibman/gists{/gist_id}","starred_url":"https://api.github.com/users/gibman/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gibman/subscriptions","organizations_url":"https://api.github.com/users/gibman/orgs","repos_url":"https://api.github.com/users/gibman/repos","events_url":"https://api.github.com/users/gibman/events{/privacy}","received_events_url":"https://api.github.com/users/gibman/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":67,"created_at":"2018-11-12T09:23:42Z","updated_at":"2018-11-20T12:38:27Z","closed_at":null,"author_association":"NONE","body":"hi.\r\n\r\nI'm running shairport-sync 3.2.1 from the moode audio project.\r\n\r\nI have 5 pi's running and they all exhibit the same misbehaviour.\r\n\r\nI also have a windows PC running tuneblade 1.7.8.0\r\n\r\nafter a few hours it seems tuneblade is unable to establish a connection with around 80% of the pi's.\r\ntuneblade automatically retries the connection over and over again as can be seen in it's UI.\r\n\r\nIt works again for a few hours if I restart the shairport-sync process.\r\n\r\nMaybe it's previous broken tuneblade connection that is still linkering on.\r\ntuneblade does crash from time to time and it could leave shairport-sync in a bad state maybe ?\r\nthis is only me guessing here :)\r\n\r\nlogs attached from one of the faulting pi's.\r\n[shairport-sync.log](https://github.com/mikebrady/shairport-sync/files/2571271/shairport-sync.log)\r\n"},"comment":{"url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/comments/440258991","html_url":"https://github.com/mikebrady/shairport-sync/issues/772#issuecomment-440258991","issue_url":"https://api.github.com/repos/mikebrady/shairport-sync/issues/772","id":440258991,"node_id":"MDEyOklzc3VlQ29tbWVudDQ0MDI1ODk5MQ==","user":{"login":"mikebrady","id":4265913,"node_id":"MDQ6VXNlcjQyNjU5MTM=","avatar_url":"https://avatars0.githubusercontent.com/u/4265913?v=4","gravatar_id":"","url":"https://api.github.com/users/mikebrady","html_url":"https://github.com/mikebrady","followers_url":"https://api.github.com/users/mikebrady/followers","following_url":"https://api.github.com/users/mikebrady/following{/other_user}","gists_url":"https://api.github.com/users/mikebrady/gists{/gist_id}","starred_url":"https://api.github.com/users/mikebrady/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mikebrady/subscriptions","organizations_url":"https://api.github.com/users/mikebrady/orgs","repos_url":"https://api.github.com/users/mikebrady/repos","events_url":"https://api.github.com/users/mikebrady/events{/privacy}","received_events_url":"https://api.github.com/users/mikebrady/received_events","type":"User","site_admin":false},"created_at":"2018-11-20T12:38:27Z","updated_at":"2018-11-20T12:38:27Z","author_association":"OWNER","body":"Okay. The earlier `failed-bathroom-cellar-shairport-sync.log` shows a familiar problem -- an incorrect cleanup of a play session's player thread when it's been `pthread_cancel`ed.\r\n\r\nHere is a valid TEARDOWN sequence:\r\n```\r\n3.478962478|RTSP thread 1 received an RTSP Packet of type \"TEARDOWN\":\r\n         0.000077396|  Type: \"CSeq\", content: \"115\"\r\n         0.000038593|  Type: \"DACP-ID\", content: \"777D92AB563BE9F8\"\r\n         0.000027083|  Type: \"Active-Remote\", content: \"1065867941\"\r\n         0.000025417|  Type: \"User-Agent\", content: \"AirPlay/373.8\"\r\n         0.000034166|Connection 1: TEARDOWN\r\n         0.000028594|player_stop\r\n         0.000022551|player_thread cancel...\r\n         0.000216770|player_thread join...\r\n         0.000312862|mutex_unlock \"&conn->ab_mutex\" at \"player.c:758\".\r\n         0.000115676|Connection 1: player thread main loop exit via player_thread_cleanup_handler.\r\n         0.000087083|Playback Stopped. Total playing time 00:03:36. Input: 44100.23, output: 44100.46 frames per second.\r\n         0.000094009|avahi_dacp_dont_monitor\r\n         0.002218264|Avahi DACP monitor successfully stopped\r\n         0.000186197|avahi_dacp_dont_monitor exit\r\n         0.000032499|Cancelling timing, control and audio threads...\r\n         0.000026406|Cancel timing thread.\r\n         0.000045052|Join timing thread.\r\n         0.000143228|Timing Receiver Cleanup.\r\n         0.000267654|shutdown timing socket.\r\n         0.000060729|close timing socket.\r\n         0.000073645|Timing Receiver Cleanup Successful.\r\n         0.000131666|Timing thread terminated.\r\n         0.000037656|Cancel control thread.\r\n         0.000042343|Join control thread.\r\n         0.000405257|Control Receiver Cleanup.\r\n         0.000050417|shutdown control socket.\r\n         0.000078749|close control socket.\r\n         0.000126145|Control Receiver Cleanup Successful.\r\n         0.000236144|Control thread terminated.\r\n         0.000041302|Cancel audio thread.\r\n         0.000048958|Join audio thread.\r\n         0.000111145|Audio Receiver Cleanup.\r\n         0.000032343|shutdown audio socket.\r\n         0.000051094|close audio socket.\r\n         0.000093697|Audio Receiver Cleanup Successful.\r\n         0.000131822|Audio thread terminated.\r\n         0.000735827|mutex_lock \"&alsa_mutex\" at \"audio_alsa.c:1051\".\r\n         0.000417966|mutex_unlock \"&alsa_mutex\" at \"audio_alsa.c:1070\".\r\n         0.000045103|mutex_lock \"&conn->reference_time_mutex\" at \"rtp.c:1031\".\r\n         0.000039844|mutex_unlock \"&conn->reference_time_mutex\" at \"rtp.c:1034\".\r\n         0.000058281|Connection 1: player thread main loop exit via player_thread_initial_cleanup_handler.\r\n         0.000266508|player_thread joined.\r\n         0.000043281|RTSP thread 1: RTSP Response:\r\n         0.000033125|  Type: \"CSeq\", content: \"115\"\r\n         0.000029895|  Type: \"Server\", content: \"AirTunes/105.1\"\r\n         0.000029688|  Type: \"Connection\", content: \"close\"\r\n         0.004237675|Connection 1: RTSP thread terminated.\r\n```\r\nNotice that line: \r\n```\r\nConnection 1: player thread main loop exit via player_thread_cleanup_handler.\r\n```\r\nThat indicates that the expected pthread cancellation sequence is taking place -- it's the main cancellation cleanup routine pushed after initialisation. But there is another one:\r\n```\r\nConnection 1: player thread main loop exit via player_thread_initial_cleanup_handler.\r\n```\r\nThis is an initial cancellation cleanup routine that was pushed as soon as the player thread started (and therefore pulled later -- cancellation cleanup routines are pushed on and popped off a stack). \r\n\r\nNow, here is a TEARDOWN sequence from the `failed-bathroom-cellar-shairport-sync.log`:\r\n```\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: RTSP thread 1 received an RTSP Packet of type \"TEARDOWN\":\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"CSeq\", content: \"6\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"Session\", content: \"1\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"User-Agent\", content: \"TuneBlade/1.0 (Windows)\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"Client-Instance\", content: \"56B6CB929BB20486\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"DACP-ID\", content: \"13EE26B2E036204E\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]:   Type: \"Active-Remote\", content: \"1918300648\"\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: Connection 1: TEARDOWN\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: TEARDOWN: synchronously terminating the player thread of RTSP conversation thread 1 (2).\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: player_stop\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: player_thread cancel...\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: player_thread join...\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: Connection 1: player thread main loop exit via player_thread_initial_cleanup_handler.\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: player_thread joined.\r\nNov 20 10:08:46 Bathroom-cellar shairport-sync[30464]: pend\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: TEARDOWN: successful termination of playing thread of RTSP conversation thread 1.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: RTSP thread 1: RTSP Response:\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]:   Type: \"CSeq\", content: \"6\"\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]:   Type: \"Server\", content: \"AirTunes/105.1\"\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]:   Type: \"Connection\", content: \"close\"\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: RTSP conversation thread 1 -- connection closed.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: Synchronously terminate playing thread of RTSP conversation thread 1.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: Successful termination of playing thread of RTSP conversation thread 1.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: Request termination of RTSP conversation thread 1.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: Unlocking play lock on RTSP conversation thread 1.\r\nNov 20 10:08:47 Bathroom-cellar shairport-sync[30464]: Connection 1: RTSP thread terminated.\r\n```\r\n\r\nThe main cancellation cleanup routine isn't performed, but the \"initial\" one is -- the one that should have been popped and executed after the main cleanup routine. This means that there must be a cancellation point in between pushing the initial one and pushing the main one in the player thread, but I can't find one, unless there is one in the code for setting up an \"mdns monitor\", which relies on the Avahi library.\r\n\r\nSo, I've moved that code to after where the main cancellation cleanup is pushed, so that there should definitely (!) be no cancellation point in the player thread until after it has pushed the main cancellation cleanup routine. I think it's worth a try.\r\n\r\n"}}
{"actor":{"display_login":"mikebrady"}}