[Asterisk-Users] MP3Player and Ringing (long)

[Daniele Orlandi]

[I'm reposting this to the asterisk-users list, since it seems to be a 
bit more active.]

Hello,

I started messing with Asterisk few days ago, so my overall knoledge
about it is still fairy superficial.
I think I found an issue with MP3Player; it can be reproducted with this
extension:

exten => 6001,1,Answer
exten => 6001,2,Background(blahblah)
exten => 6001,3,Ringing
exten => 6001,4,Wait(2)
exten => 6001,5,MP3Player(pippo.mp3)

What I think it is happening is that <Background> plays its GSM file
setting the write format to 2 (GSM), <Ringing> starts the generator
setting the write format to 64 (Linear PCM) saving the old write format
2; MP3Player starts, set the write format to 64. When it calls ast_write
to write the first stream, ast_release_generator is called and restores
the write format to 2 (GSM); further writes produce codec errors since
MP3Players writes Linear PCM frames.

I extracted some debug log:

  Jun  5 01:55:33 DEBUG[1158913328]: File chan_sip.c, Line 1327
(sip_alloc): Allocating new SIP call for
7a655bae-29f17562-197726d5 at 62.212.12.21
Jun  5 01:55:33 DEBUG[1158913328]: File chan_sip.c, Line 3359
(check_user): Setting NAT on RTP to 0
Jun  5 01:55:33 DEBUG[1158913328]: File chan_sip.c, Line 2899
(build_route): build_route: Contact hop: 5010 <sip:5010 at 62.212.12.21>
Jun  5 01:55:33 DEBUG[1236360496]: File pbx.c, Line 1116
(pbx_extension_helper): Launching 'Answer'
Jun  5 01:55:33 DEBUG[1236360496]: File chan_sip.c, Line 934
(sip_answer): sip_answer(SIP/5010-d3c4)
Jun  5 01:55:33 DEBUG[1236360496]: File pbx.c, Line 1116
(pbx_extension_helper): Launching 'BackGround'
Jun  5 01:55:33 DEBUG[1236360496]: File channel.c, Line 1381
(ast_set_write_format): Set channel SIP/5010-d3c4 to write format 2
Jun  5 01:55:33 DEBUG[1236360496]: File rtp.c, Line 838 (ast_rtp_write):
Ooh, format changed from 0 to 4
Jun  5 01:55:36 DEBUG[1158913328]: File chan_sip.c, Line 521
(__sip_ack): Stopping retransmission on
'7a655bae-29f17562-197726d5 at 62.212.12.21' of Response 26024: Found
Jun  5 01:55:36 DEBUG[1158913328]: File chan_sip.c, Line 521
(__sip_ack): Stopping retransmission on
'7a655bae-29f17562-197726d5 at 62.212.12.21' of Response 26024: Not Found
Jun  5 01:55:36 DEBUG[1158913328]: File chan_sip.c, Line 521
(__sip_ack): Stopping retransmission on
'7a655bae-29f17562-197726d5 at 62.212.12.21' of Response 26024: Not Found
Jun  5 01:55:37 DEBUG[1236360496]: File pbx.c, Line 1116
(pbx_extension_helper): Launching 'Ringing'
Jun  5 01:55:37 DEBUG[1236360496]: File channel.c, Line 1163
(ast_indicate): Driver for channel 'SIP/5010-d3c4' does not support
indication 3, emulating it
Jun  5 01:55:37 DEBUG[1236360496]: File channel.c, Line 747
(ast_activate_generator): ast_activate_generator
Jun  5 01:55:37 DEBUG[1236360496]: File channel.c, Line 1381
(ast_set_write_format): Set channel SIP/5010-d3c4 to write format 64
Jun  5 01:55:37 DEBUG[1236360496]: File pbx.c, Line 1116
(pbx_extension_helper): Launching 'Wait'
Jun  5 01:55:37 DEBUG[1158913328]: File chan_sip.c, Line 521
(__sip_ack): Stopping retransmission on
'7a655bae-29f17562-197726d5 at 62.212.12.21' of Response 26024: Not Found
Jun  5 01:55:38 DEBUG[1236360496]: File pbx.c, Line 1116
(pbx_extension_helper): Launching 'MP3Player'
Jun  5 01:55:38 DEBUG[1236360496]: File channel.c, Line 1381
(ast_set_write_format): Set channel SIP/5010-d3c4 to write format 64
Jun  5 01:55:39 DEBUG[1236360496]: File channel.c, Line 1298
(ast_write): ast_write -> ast_deactivate_generator
Jun  5 01:55:39 DEBUG[1236360496]: File channel.c, Line 734
(ast_deactivate_generator): ast_deactivate_generator
Jun  5 01:55:39 DEBUG[1236360496]: File indications.c, Line 62
(playtones_release): playtones_release
Jun  5 01:55:39 DEBUG[1236360496]: File channel.c, Line 1381
(ast_set_write_format): Set channel SIP/5010-d3c4 to write format 2

After that, the console is filled with:

WARNING[1236360496]: File codec_gsm.c, Line 136 (gsmtolin_framein): Huh?
  A GSM frame that isn't a multiple of
33 or 65 bytes long from mp3_exec (320)

I attempted to dig into this thing, if I used another call to
<Background> (even with another format) the problem didn't show up since
ast_openstream takes care of calling ast_deactivate_generator, so I
simply added:

         if (chan->generator)
                 ast_deactivate_generator(chan);

to app_mp3.c and the problem seems to go away.

I think that the real question is if it is wise to rely on a side effect
  of ast_openstream in applications and on the other side if it is wise
to delegate the to the application the call to ast_deactivate_generator.

I have the feeling that there's a lack of precise semantic in the API to
access channels and in my experience this often is the cause of subtle
bugs. Of course, since I think I'm missing many aspects of Asterisk I
may be completely wrong, in this case I'd appreciate very much some
clarification about the interactions between applications, generator and
streams with respect to the channel.

Thanks in advance to everyone who took the time to read this :^)

Bye!

-- 
  Daniele Orlandi