[Pianod] v234 gdb logs

[Bruce M. Sheplan via Pianod]

-- Bringing this back to the mailing list ---


Thanks for the dump—this is helpful.  Is it always as it’s changing tracks
> that it dies?  If so, I’m currently thinking a race condition related to
> this… got ideas.


This is what the logs look like when pianod crashes, I think your theory of
it crashing when changing tracks is true:

Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: Releasing
>> song "DUELE EL CORAZON (Feat. Gente De Zona & Wisin) [Remix]" (ID
>> 2sPYq-Xoje8vjI0oX8KsyxXsI2oiA2j5oqtnNZ5rr1IHy9ZNbx0Au6RBti0b6IKm_jMqWawKrFIsME),
>> useCount=2
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: Releasing
>> song "Dos Historias Iguales" (ID
>> 2sPG0LMmU5fCnQ0oX8KsyxXsI47D3yrJf4T1Oa1wNdpYk3R5p3Xw4Pm-N9qyqTum7X8XlngTJ_v2Oo),
>> useCount=1
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 004 Track
>> playback complete
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 111 ID:
>> 2sPMVyr0T-kqjc0oX8KsyxXsOesgO43MApUx0ZEUgfSrwRZNbx0Au6RBp0V3Vhgv8rvHJY-mmn28ck
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 112 Album:
>> De Viaje
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 113 Artist:
>> Sin Bandera
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 114 Title:
>> Mientes Tan Bien
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 118
>> CoverArt:
>> http://mediaserver-cont-dc6-1-v4v6.pandora.com/images/public/rovi/albumart/3/2/3/3/037627063323_500W_500H.jpg
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 115
>> Playlist: Laura Pausini Radio
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 117 SeeAlso:
>> http://www.pandora.com/sin-bandera/de-viaje/mientes-tan-bien?dc=232&ad=1:36:1:78258::0:0:0:0:641:059:TX:48029:0:0:0:0:0:1
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 123 Source:
>> pandora
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 124 Name:
>> pandora
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 116 Rating:
>> neutral 3.0
>
> Aug 22 20:06:23 homemedia pianod[19592]: 2016-08-22 20:06:23: 120
>> PlaylistRating: unrated
>
> Aug 22 20:07:24 homemedia pianod[19592]: 2016-08-22 20:07:24:
>> pandorasuggestions.cpp:179 purge (LOG_CACHES): Pandora suggestion cache:
>> Pre-purge, size= 0
>
> Aug 22 20:07:24 homemedia pianod[19592]: 2016-08-22 20:07:24:
>> pandorasuggestions.cpp:189 purge (LOG_CACHES): Pandora suggestion cache:
>> Post-purge, size= 0
>
> Aug 22 20:08:34 homemedia pianod[19592]: 2016-08-22 20:08:34:
>> musictypes.cpp:747 purge (LOG_CACHES): pandora#pandora: Pre-purge, size= 25
>
> Aug 22 20:08:34 homemedia pianod[19592]: 2016-08-22 20:08:34: Releasing
>> song "Amor Real" (ID
>> 2sPciYm6c10Rno0oX8KsyxXsFZSjbHbNk171Oa1wNdpYk1ZNbx0Au6RBv3lLIUCjl-I7r30bNHcQSM),
>> useCount=0
>
> Aug 22 20:08:34 homemedia pianod[19592]: 2016-08-22 20:08:34: Releasing
>> playlist "Laura Pausini Radio" (ID 2p219261310276913318), useCount=0
>
> Aug 22 20:08:34 homemedia pianod[19592]: 2016-08-22 20:08:34:
>> musictypes.cpp:764 purge (LOG_CACHES): pandora#pandora: Post-purge, size= 24
>
> Aug 22 20:09:44 homemedia pianod[19592]: 2016-08-22 20:09:44:
>> pandorasuggestions.cpp:179 purge (LOG_CACHES): Pandora suggestion cache:
>> Pre-purge, size= 0
>
> Aug 22 20:09:44 homemedia pianod[19592]: 2016-08-22 20:09:44:
>> pandorasuggestions.cpp:189 purge (LOG_CACHES): Pandora suggestion cache:
>> Post-purge, size= 0
>
> Aug 22 20:10:13 homemedia kernel: [87292.387390] pianod[19592]: segfault
>> at 2c ip b4b3b9cd sp bff87c70 error 4 in libgstplayback.so[b4b2d000+68000]
>
> Aug 22 20:10:13 homemedia systemd[1]: pianod.service: Main process exited,
>> code=killed, status=11/SEGV
>
> Aug 22 20:10:13 homemedia systemd[1]: pianod.service: Unit entered failed
>> state.
>
> Aug 22 20:10:13 homemedia systemd[1]: pianod.service: Failed with result
>> 'signal'.
>
>
>

 I'm having a regression when starting as a service where it hangs, seems
> to work fine on the command line.


I was able to eliminate this problem by removing the following from my
startscript, I was using it to explicitly set the output of the pianod room
to the first output, but apparently this is not needed and seems to cause
problems when included in startscript:

ROOM ENTER pianod
> ROOM RECONFIGURE DEVICE "alsasink device=hw:0"


So far I think I have relatively stable config on 234 except for the rare
crashes, I have switched to this version for daily use now.

- B

On Mon, Aug 22, 2016 at 2:28 PM, Bruce M. Sheplan <bruce at sheplan.com> wrote:

> Thanks for the dump—this is helpful.  Is it always as it’s changing tracks
>> that it dies?  If so, I’m currently thinking a race condition related to
>> this… got ideas.
>
>
> I think so, but I'm not 100% sure if its only when changing tracks.  I
> have only noticed that it crashes when I notice the music is missing.
>
> Also regarding your issue with hw:1 is that when starting as a sevice? I'm
> having a regression when starting as a service where it hangs, seems to
> work fine on the command line.  I have yet to try this out without setting
> up the other rooms so I dont know if its related to creating the additional
> rooms.
>
> Since one of the major differences between cmdline and systemd startup is
> where the stdout and stderr are hooked up to, I suspect there is a race
> condition related to how fast the logger can output and whatever the
> threads are doing when its starting up.  The other reason to think this is
> that if I change the logging flags from 0xffff to 0x0000 the service works
> more often (~40% of the time), changing the debug level should not change
> behavior just the amount of output
>
> For reference this my currently working commandline for configuring the
> output device:
>
>> ROOM CREATE pandora2 DEVICE "alsasink device=hw:2"
>
> or
>
>> ROOM RECONFIGURE DEVICE "alsasink device=hw:2"
>
>
> - Bruce
>
> On Mon, Aug 22, 2016 at 2:13 PM, Perette Barella <perette at barella.org>
> wrote:
>
>> On 2016年08月22日, at 13:15, Bruce M. Sheplan <bruce at sheplan.com> wrote:
>>
>>
>> Here is the gdb dump generated from the core dump.
>>
>>
>> Bruce,
>>
>> Thanks for the dump—this is helpful.  Is it always as it’s changing
>> tracks that it dies?  If so, I’m currently thinking a race condition
>> related to this… got ideas.
>>
>> r236/237 don’t have much changed for gstreamer, it’s been ffmpeg stuff.
>>  r237 finishes updates to get rid of deprecated APIs with ffmpeg 3.1.  So
>> the issue there stems from read-the-code documentation: AVFormat is the
>> high-level reader, which contains some number of AVStreams, each of which
>> has a reference to an AVCodecContext.  The obvious-to-me interpretation of
>> this was “use this stream-provided AVCodecContext so it associates the
>> codec with the stream,” when in fact the two are never related.  The
>> correct approach is to allocate my own codec context, copy the one supplied
>> (or in 3.1, copy the parameters structure supplied) by the stream to get
>> its details.
>>
>> Perette
>>
>> --
>> Perette Barella • perette at barella.org • 585-317-3013
>> 176 Middlesex Road, Rochester NY 14610
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.deviousfish.com/pipermail/pianod-deviousfish.com/attachments/20160823/5db88114/attachment.htm>