search

philippe44 / AirConnect

Use AirPlay to stream to UPnP/Sonos & Chromecast devices
Other
3.43k stars 216 forks source link

v1.1.5 exits with malloc #465

Closed jottr closed 10 months ago

jottr commented 1 year ago

I'm not sure if this is a duplicate of https://github.com/philippe44/AirConnect/issues/464, please close if this is caused by the same bug.
See debug.log.


❯ ~/aircast-macos-arm64-static -f debug.log                                                            
[1]    74199 abort      ~/aircast-macos-arm64-static -f debug.log                                         

❯ echo $?                                                                                    
134
philippe44 commented 1 year ago

Does it happen exactly under the same conditions? What happens with just one player?

jottr commented 1 year ago

Does it happen exactly under the same conditions?

It happens every time I connect to the player.

What happens with just one player?

I'm not sure I understand your question.

philippe44 commented 1 year ago

What happens with just one player? I'm not sure I understand your question.

Are you playing to a group of speakers or is this a standalone device? What device(s) type(s) is this?

jottr commented 1 year ago

This is a single Chromecast Audio standalone device.

philippe44 commented 1 year ago

ah ... weird. Was this happening with previous versions?

philippe44 commented 1 year ago

And can you try the x86 version?

ffmusic commented 1 year ago

Same error here with version 1.16, even with the x86 version: aircast-macos-x86_64-static.uu(20042,0x700005faa000) malloc: *** set a breakpoint in malloc_error_break to debug zsh: abort

philippe44 commented 1 year ago

I'm sorry but I'm totally unable to reproduce that. I've ran it under valgrind and debug tools and it did not cause a problem.

jottr commented 1 year ago

Ok, what could we do to help? I have little knowledge of the protocols involved.

philippe44 commented 1 year ago

Do you all have M1 Mac?

jottr commented 1 year ago

I just tested the x86 version on an x86 Mac.
The issue seems to not exist on that platform.

ffmusic commented 1 year ago

Mine is an Intel Mac

jottr commented 1 year ago

Mine is an Intel Mac

That's weird. I couldn't reproduce on my Intel Mac. For me the issue only seems to exist on the M2 instance.

philippe44 commented 1 year ago

Unfortunately I can't test that

jottr commented 1 year ago

@ffmusic says he's not on Apple Silicon. I have access to both platforms.

I'm willing to help debug if you tell me what you need.

philippe44 commented 1 year ago

Got confused by the posts. Can you track with what version it started? Don't used only the published ones, just use GitHub directly and follow the different commits

frankie2784 commented 1 year ago

I have the same issue on Mac Intel. Works fine on 1.0.8, breaks at 1.1.1

...

[14:40:42.798796] CastSocketThread:674 [0x7ff5500179b0]: Media session id 1  
[14:40:42.852910] ProcessQueue:456 [0x7ff5500179b0]: Processing PLAY (id:6)  
[14:40:42.993737] ProcessQueue:449 [0x7ff5500179b0]: Processing VOLUME (id:8)  
[14:40:42.993836] MRThread:292 [0x7ff5500179b0]: Cast playing  
[14:40:43.002860] ProcessQueue:456 [0x7ff5500179b0]: Processing PLAY (id:9)  
aircast-macos-x86_64-static(5194,0x70000a1b2000) malloc: *** error for object 0x600002158960: pointer being freed was not allocated  
aircast-macos-x86_64-static(5194,0x70000a1b2000) malloc: *** set a breakpoint in malloc_error_break to debug  
Abort trap: 6
philippe44 commented 1 year ago

Thanks, that's very useful information. Could you tell me if 1.0.16 still works for you? It's not a "released" version but if you look at the commits on GitHub, you can find it there and the binaries are uploaded as well

frankie2784 commented 1 year ago

1.0.17 works, 1.1.0 breaks

philippe44 commented 1 year ago

Perfect, this is what I needed

philippe44 commented 1 year ago

If any of you has gdb (or similar) installed, that would be helpful to run aircast under it so I can figure out where the issue happens because so far I can't find it. I understand it's related to the artwork and other changes I added in 1.1.x but can't reproduce a crash on any platform I have. I've tweaked a few things in 1.1.7 but I don't think it has any connection

frankie2784 commented 1 year ago

I have installed gdb, but have never used it before. The documentation is a little confusing. Can you let me know the commands needed to run aircast under it?

On Sat, 20 May 2023 at 23:54, philippe44 @.***> wrote:

If any of you has gdb (or similar) installed, that would be helpful to run aircast under it so I can figure out where the issue happens because so far I can't find it. I understand it's related to the artwork and other changes I added in 1.1.x but can't reproduce a crash on any platform I have. I've tweaked a few things in 1.1.7 but I don't think it has any connection

— Reply to this email directly, view it on GitHub https://github.com/philippe44/AirConnect/issues/465#issuecomment-1555916680, or unsubscribe https://github.com/notifications/unsubscribe-auth/AETVUIUNGI6TY42VQBMKU43XHDEJ5ANCNFSM6AAAAAAX3K6O64 . You are receiving this because you commented.Message ID: @.***>

-- π

philippe44 commented 1 year ago

Just type "gdb ./aircast-macos-x86_64-static", assuming you're une the directory where aircast is. Type "run" at the prompt and it should run normally. When it crashes, it should telle where and at the prompt type "backtrace" (from memory, I always forget this one, type help otherwise) and give me the result

frankie2784 commented 1 year ago

Doesn't seem to do anything using "gdb ./aircast-macos-x86_64-static"

All I'm getting is this and nothing further:

...
Reading symbols from ./aircast-macos-x86_64-static...
(No debugging symbols found in ./aircast-macos-x86_64-static)
(gdb) run
Starting program: /Users/frankiemacbook/AirConnect/aircast-macos-x86_64-static 
[New Thread 0x1103 of process 93097]
philippe44 commented 1 year ago

This is strange... it should simply run

jottr commented 1 year ago

Output of lldb


[18:36:24.951045] main:912 Starting aircast version: v1.1.5 (May  7 2023 @ 13:42:24)
[18:36:24.951217] main:919 no config file, using defaults
[18:36:24.951249] Start:679 Binding to 192.168.99.221
[18:36:24.951458] Start:704 Starting pico HTTP server on port 53651
[18:36:25.368629] AddCastDevice:644 [0x108038000]: adding renderer (SHIELD) with mac CCCC7BD4F04B
[18:36:25.372914] AddCastDevice:644 [0x1080389b0]: adding renderer (Living Room speaker) with mac CCCC969AEA09
[18:36:31.872848] rtsp_thread:338 got RTSP connection 10
[18:36:31.962033] handle_rtsp:385 [0x103a05e20]: challenge xR/xTr6hGSRKlnDdm437+A==
[18:36:31.967079] handle_rtsp:379 [0x103a05e20]: received ANNOUNCE
[18:36:31.970623] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 4

[18:36:31.971251] handle_rtsp:379 [0x103a05e20]: received SETUP
[18:36:31.971332] raopst_init:378 [0x110008000]: UDP port-0 51024
[18:36:31.971374] raopst_init:378 [0x110008000]: UDP port-1 57173
[18:36:31.971444] raopst_init:378 [0x110008000]: UDP port-2 52538
[18:36:31.971571] raopst_init:396 [0x110008000]: HTTP listening port 53659
[18:36:31.971673] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Transport: RTP/AVP/UDP;unicast;mode=record;control_port=57173;timing_port=52538;server_port=51024
Session: DEADBEEF
Audio-Jack-Status: connected; type=analog
CSeq: 5

[18:36:31.972205] handle_rtsp:379 [0x103a05e20]: received RECORD
[18:36:31.972212] raopst_record:502 [0x110008000]: record 0 0
[18:36:31.972214] raop_cb:182 [0x1080389b0]: Stream
[18:36:31.972228] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 6

[18:36:31.972842] rtp_thread_func:736 [0x110008000]: 1st sync packet received
[18:36:31.973474] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:31.973487] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -20.000000
[18:36:31.973502] CastSetDeviceVolume:375 [0x1080389b0]: Queuing SET_VOLUME
[18:36:31.973505] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.3333
[18:36:31.973522] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 7

[18:36:31.990460] flac_init:195 [0x110008000]: Using FLAC-0 (0x6000000040a0)
[18:36:31.990509] buffer_put_packet:620 [0x110008000]: fill [level:1] [W:40242 R:40242]
[18:36:31.992230] handle_rtsp:379 [0x103a05e20]: received FLUSH
[18:36:31.992244] raopst_flush:470 [0x110008000]: FLUSH ignored as same as RECORD (40242 - 1170587469)
[18:36:31.992247] raopst_flush:486 [0x110008000]: flush 40242 1170587469
[18:36:31.992303] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 8

[18:36:32.499934] raop_cb:205 [0x1080389b0]: Play
[18:36:32.520224] search_remote_cb:641 [0x103a05e20]: found ActiveRemote for E3457EB65F38877C at 192.168.99.221:53654
[18:36:32.727713] CastConnect:239 [0x1080389b0]: SSL connection opened [0x104011000]
[18:36:32.728098] CastLoad:177 [0x1080389b0]: Queuing LOAD
[18:36:32.728116] CastPlay:264 [0x1080389b0]: Queuing PLAY
[18:36:32.728124] CastSetDeviceVolume:375 [0x1080389b0]: Queuing SET_VOLUME
[18:36:32.774846] CastSocketThread:631 [0x1080389b0]: Launching receiver 1
[18:36:32.824646] CastSocketThread:659 [0x1080389b0]: Receiver launched
[18:36:32.824776] ProcessQueue:448 [0x1080389b0]: Processing VOLUME (id:3)
[18:36:32.980300] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:32.980400] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 9

[18:36:32.982691] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:32.982751] CastPlay:264 [0x1080389b0]: Queuing PLAY
[18:36:32.982758] handle_rtsp:571 [0x103a05e20]: received metadata
    artist: 
    album:  
    title:  
[18:36:32.982793] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 10

[18:36:33.900886] ProcessQueue:485 [0x1080389b0]: Processing LOAD (id:4)
[18:36:34.011791] http_thread_func:1058 [0x110008000]: got HTTP connection 17 (silent frames 0)
[18:36:34.013141] handle_http:1234 [0x110008000]: received GET HTTP/1.1
Host: 192.168.99.221:53659
Connection: keep-alive
User-Agent: Mozilla/5.0 (X11; Linux armv7l) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/90.0.4430.225 Safari/537.36 CrKey/1.56.500000
Range: bytes=0-
Accept-Encoding: identity;q=1, *;q=0
Accept: */*
CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":true,"display_supported":false,"hi_res_audio_supported":true,"remote_control_input_supported":false,"touch_input_supported":false}
Accept-Language: en-US,en;q=0.9

[18:36:34.013233] handle_http:1279 [0x110008000]: responding: HTTP/1.0 200 OK
Server: HairTunes
Content-Type: audio/flac
Connection: close

[18:36:34.013247] _buffer_get_frame:959 [0x110008000]: drain [level:252 gap:-283] [W:40494 R:40242] [R:0 S:0 F:0]
[18:36:34.142789] CastSocketThread:673 [0x1080389b0]: Media session id 4
[18:36:34.284503] ProcessQueue:455 [0x1080389b0]: Processing PLAY (id:6)
[18:36:34.368352] ProcessQueue:448 [0x1080389b0]: Processing VOLUME (id:8)
[18:36:34.368765] MRThread:290 [0x1080389b0]: Cast playing
[18:36:35.431768] ProcessQueue:455 [0x1080389b0]: Processing PLAY (id:10)
[18:36:36.070396] buffer_put_packet:620 [0x110008000]: fill [level:4] [W:40754 R:40751]
[18:36:36.089539] _buffer_get_frame:959 [0x110008000]: drain [level:0 gap:1728] [W:40754 R:40754] [R:0 S:0 F:0]
[18:36:38.431268] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:38.431290] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -18.750000
[18:36:38.433388] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.3750
[18:36:38.433433] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 14

[18:36:40.180103] buffer_put_packet:620 [0x110008000]: fill [level:1] [W:41266 R:41266]
[18:36:40.199410] _buffer_get_frame:959 [0x110008000]: drain [level:3 gap:1706] [W:41269 R:41266] [R:0 S:0 F:0]
[18:36:41.374664] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:41.374687] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -20.625000
[18:36:41.374963] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.3125
[18:36:41.374982] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 16

[18:36:41.394782] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:41.394840] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -22.500000
[18:36:41.394882] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.2500
[18:36:41.394896] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 17

[18:36:41.889869] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:41.889957] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -20.625000
[18:36:41.890249] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.3125
[18:36:41.890309] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 18

[18:36:41.976781] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:41.976953] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -18.750000
[18:36:41.977300] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.3750
[18:36:41.977320] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 19

[18:36:42.104840] handle_rtsp:379 [0x103a05e20]: received SET_PARAMETER
[18:36:42.104864] handle_rtsp:552 [0x103a05e20]: SET PARAMETER volume -16.875000
[18:36:42.105027] raop_cb:232 [0x1080389b0]: Volume[0..1] 0.4375
[18:36:42.105057] handle_rtsp:598 [0x103a05e20]: responding:
RTSP/1.0 200 OK
Audio-Jack-Status: connected; type=analog
CSeq: 21

aircast-macos-arm64-static(7714,0x1703ff000) malloc: *** error for object 0x6000021249d8: pointer being freed was not allocated
aircast-macos-arm64-static(7714,0x1703ff000) malloc: *** set a breakpoint in malloc_error_break to debug
(lldb)

Breaking on the malloc_error_break symbol displays the following in Xcode:

libsystem_malloc.dylib`malloc_error_break:
->  0x19572643c <+0>:  pacibsp 
    0x195726440 <+4>:  stp    x29, x30, [sp, #-0x10]!
    0x195726444 <+8>:  mov    x29, sp
    0x195726448 <+12>: nop    
    0x19572644c <+16>: ldp    x29, x30, [sp], #0x10
    0x195726450 <+20>: retab

I have zero experience with debugging Xcode C projects. Not sure where to take it from here. Still willing to help resolve this issue.

Interestingly, when running v1.1.5 as an x86 static binary via Rosetta the issue remains. At least on Apple Silicon.

leifan89 commented 1 year ago

Setup:

Confirmed the following behaviors:

philippe44 commented 1 year ago

I don't know what to do about this one. This only happens on macOS arm64. I don't have such device and valgrind on Linux (memory checker) does not give me anything nor does code review

jottr commented 1 year ago

Ok. So it seems that the error has been introduced in 1.1.0 where you add the metadata feature. I noticed, that the metadata fields are not being populated.

Snip from the log:

[18:36:32.982758] handle_rtsp:571 [0x103a05e20]: received metadata
    artist: 
    album:  
    title:

Maybe you could add some error checking and handling to code that relates to this feature?

philippe44 commented 1 year ago

I will recheck but the metadata can be not populated, it is an expected case

philippe44 commented 1 year ago

Can you try 1.1.7 (it's not in the released versions I think). There is something weird in your log and I wat to make sure it is not due to a library not being regenerated.

jottr commented 1 year ago

Are you sure you mean 1.1.7? The latest tag I find is 1.1.5.

git tag -l 

0.2.0.6
0.2.1.1
0.2.21.3
0.2.22.0
0.2.22.1
0.2.25.0
0.2.26.1
0.2.27.1
0.2.28.3
0.2.28.5
0.2.30
0.2.41.0
0.2.41.2
0.2.42.0
0.2.42.1
0.2.43.1
0.2.44.1
0.2.50.2
0.2.50.5
0.2.51.1
1.0.0
1.0.1
1.0.2
1.0.3
1.0.5
1.0.8
1.1.1
1.1.3
1.1.5
philippe44 commented 1 year ago

Yes, it's not a tagged version. Just download the binary in the bin/ folder on GitHub

jottr commented 1 year ago

See the debug log here

philippe44 commented 1 year ago

So there is no versioning error in my pre-compiled library I'm using. Any chance you can find somebody who know how to make it run under gdb? That would help tremendously

philippe44 commented 1 year ago

Oh, can you also sett all log levels to "info" by adding "-d all=info" on the command line and see if you get something more

jottr commented 1 year ago

Oh, can you also sett all log levels to "info" by adding "-d all=info" on the command line and see if you get something more

https://gist.github.com/jottr/747154a93102b839adeea269942a72b8

So there is no versioning error in my pre-compiled library I'm using. Any chance you can find somebody who know how to make it run under gdb? That would help tremendously

It seems that GCC does not yet officially support Apple Silicon. There seems to be some effort to get it working though.

philippe44 commented 1 year ago

ok, not much more unfortunately. Can you verify that thesecrash as well (version should be 1.1.8-tmp-1 aircast-macos-arm64-static.zip

jottr commented 11 months ago

Please excuse the delayed response. I just tested your binary. The crash still happens with this version.

philippe44 commented 10 months ago

Should finally be fixed in 1.1.8

jottr commented 10 months ago

I just tested. It seems to be working so far. Great work.

philippe44 commented 10 months ago

I just tested. It seems to be working so far. Great work.

Thanks ... too me a long while 😄

jottr commented 10 months ago

I hope it's ok that I closed the issue. :)

leifan89 commented 10 months ago

I also confirm that this worked on my MBA. Thank you very much!

philippe44 commented 10 months ago

Thanks!