[Home]

Summary:ASTERISK-13499: mpg123 crashes when trying to play stream.
Reporter:Jonn Taylor (jonnt)Labels:
Date Opened:2009-02-02 16:05:23.000-0600Date Closed:2011-06-07 14:07:22
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_musiconhold
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) debug9_verbose9.log
( 1) musiconhold_additional.conf
( 2) musiconhold_custom.conf
( 3) musiconhold.conf
Description:mpg123 crashes when trying to play stream. Also seems that format_mp3 loads but does to work.

****** ADDITIONAL INFORMATION ******

[Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Parsing '/etc/asterisk/musiconhold.conf': [Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Found
[Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Parsing '/etc/asterisk/musiconhold_custom.conf': [Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Found
[Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Parsing '/etc/asterisk/musiconhold_additional.conf': [Feb  2 15:58:36] VERBOSE[18417] logger.c:   == Found
[Feb  2 15:58:36] WARNING[18417] res_musiconhold.c: Cannot open dir /dev/null or dir does not exist
[Feb  2 15:58:36] VERBOSE[18417] logger.c:  res_musiconhold.so => (Music On Hold Resource)
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Added extension 'musiconhold' priority 1 to app-blackhole (0x9f318f0)
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Added extension 'musiconhold' priority 2 to app-blackhole (0x9f318f0)
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Added extension 'musiconhold' priority 3 to app-blackhole (0x9f318f0)
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Registered extension context 'macro-setmusic' (0xb7ee2880) in local table 0xb7e32c90; registrar: pbx_config
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Added extension 's' priority 1 to macro-setmusic (0xb7ee2880)
[Feb  2 15:58:37] VERBOSE[18417] logger.c:     -- Added extension 's' priority 2 to macro-setmusic (0xb7ee2880)
[Feb  2 15:59:41] VERBOSE[18510] logger.c:   == Parsing '/etc/asterisk/musiconhold.conf': [Feb  2 15:59:41] DEBUG[18510] config.c: Parsing /etc/asterisk/musiconhold.conf
[Feb  2 15:59:41] VERBOSE[18510] logger.c:   == Parsing '/etc/asterisk/musiconhold_custom.conf': [Feb  2 15:59:41] DEBUG[18510] config.c: Parsing /etc/asterisk/musiconhold_custom.conf
[Feb  2 15:59:41] VERBOSE[18510] logger.c:   == Parsing '/etc/asterisk/musiconhold_additional.conf': [Feb  2 15:59:41] DEBUG[18510] config.c: Parsing /etc/asterisk/musiconhold_additional.conf
[Feb  2 15:59:41] WARNING[18510] res_musiconhold.c: Cannot open dir /dev/null or dir does not exist
[Feb  2 15:59:41] DEBUG[18510] res_musiconhold.c: killing 18431!
[Feb  2 15:59:42] DEBUG[18510] res_musiconhold.c: mpg123 pid 18431 and child died after 0 bytes read
Comments:By: Jonn Taylor (jonnt) 2009-02-02 16:07:50.000-0600

Can play from command line.

High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
version 1.3.1; written and copyright by Michael Hipp and others
free software (LGPL/GPL) without any warranty but with best wishes
Decoder: i386

Audio driver: file/raw/test
Audio device: <none>
Audio capabilities:
(matrix of [S]tereo or [M]ono support for sample format and rate in Hz)
       |  s16  |  u16  |  u8   |  s8   | ulaw  | alaw  |
--------------------------------------------------------
 8000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
11025  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
12000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
16000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
22050  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
24000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
32000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
44100  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
48000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |
 8000  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |  M/S  |


playlist in normal order:
http://208.122.59.30:7656

Info: ICY interval 8192

Note: Junk at the beginning (0xca5d681d)
Directory: http://
Playing MPEG stream 1 of 1: 208.122.59.30:7656 ...
ICY-NAME: S K Y . F M - Country - today's Hit Country with a mix of your favorites
ICY-URL: http://www.sky.fm/country/
MPEG 2.0, Layer: III, Freq: 16000, mode: Single-Channel, modext: 0, BPF : 108
Channels: 1, copyright: No, original: Yes, CRC: No, emphasis: 0.
Bitrate: 24 kbit/s Extension value: 0
Frame#    74 [    0], Time: 00:02.66 [00:00.00], RVA:   off, Vol:  25( 25)
ICY-META: StreamTitle='Rogers Randy Band - In My Arms Instead [Long Intro]';StreamUrl='';
Frame#  2501 [    0], Time: 01:30.03 [00:00.00], RVA:   off, Vol:  25( 25)[readers.c:150] error: reading the rest of 4096
[mpg123.c:570] error: ...in decoding next frame: Error reading the stream. (code 18)
Frame#  2501 [    0], Time: 01:30.03 [00:00.00], RVA:   off, Vol:  25( 25)
[1:30] Decoding of 208.122.59.30:7656 finished.
By: Leif Madsen (lmadsen) 2009-02-02 17:43:30.000-0600

Can you set directory= to something other than /dev/null? That won't work.
By: Tilghman Lesher (tilghman) 2009-02-02 17:52:33.000-0600

Well, the problem is that you've got mpg321, not mpg123.  The version number is the clear sign that you're using the wrong program.  The correct version is 0.59r.
By: Jonn Taylor (jonnt) 2009-02-02 19:47:21.000-0600

I am using centos 5 and mpg123 from DAG. Here is the output..

[Feb  2 19:37:25] VERBOSE[26655] logger.c:   == Parsing '/etc/asterisk/musiconhold.conf': [Feb  2 19:37:25] DEBUG[26655] config.c: Parsing /etc/asterisk/musiconhold.conf
[Feb  2 19:37:25] VERBOSE[26655] logger.c:   == Parsing '/etc/asterisk/musiconhold_custom.conf': [Feb  2 19:37:25] DEBUG[26655] config.c: Parsing /etc/asterisk/musiconhold_custom.conf
[Feb  2 19:37:25] VERBOSE[26655] logger.c:   == Parsing '/etc/asterisk/musiconhold_additional.conf': [Feb  2 19:37:25] DEBUG[26655] config.c: Parsing /etc/asterisk/musiconhold_additional.conf
[Feb  2 19:37:25] DEBUG[26655] res_musiconhold.c: killing 26584!
[Feb  2 19:37:25] DEBUG[26655] res_musiconhold.c: mpg123 pid 26584 and child died after 41 bytes read
[Feb  2 19:37:39] VERBOSE[26661] logger.c:     -- Started music on hold, class 'Christian-Music', on channel 'SIP/4002-b7d1a810'
[Feb  2 19:37:39] VERBOSE[26661] logger.c:     -- Stopped music on hold on SIP/4002-b7d1a810



Also see http://www.mpg123.de/asterisk.shtml
By: Tilghman Lesher (tilghman) 2009-02-02 23:07:52.000-0600

Please upload your musiconhold.conf, musiconhold_custom.conf, and musiconhold_additional.conf.
By: Jonn Taylor (jonnt) 2009-02-03 07:23:07.000-0600

The musiconhold_custom.conf has everything commented out. I am using freepbx 2.5.1.
By: Tilghman Lesher (tilghman) 2009-02-04 12:43:24.000-0600

Your directory entry is this:
[Christian-Music]
mode=custom
application=/usr/bin/mpg123 -q -s --mono -r 8000 -f 8192 http://160.79.128.40:7786/
format=ulaw

This entry is invalid, as is.  There are two ways to make this work:

[Christian-Music]
mode=custom
application=/usr/bin/mpg123 -q -s --mono -r 8000 -f 8192 http://160.79.128.40:7786/
format=ulaw
directory=nodir

[Christian-Music]
mode=custom
application=/usr/bin/mpg123 -q -s --mono -r 8000 -f 8192
directory=http://160.79.128.40:7786/
format=ulaw
By: Jonn Taylor (jonnt) 2009-02-04 21:29:06.000-0600

Down graded to 1.6.0.1 and res_musiconhold works fine with mpg123. Test with mpg123 1.6.4. Also tested with 1.6.0.3 and mpg123 does not work.
By: Tilghman Lesher (tilghman) 2009-02-05 01:01:34.000-0600

Have you changed your configs to what I suggested and tried that?
By: Jonn Taylor (jonnt) 2009-02-05 07:16:53.000-0600

Yes I did and got the same results. mpg123 crash. The only way it would work is if I went to 1.6.0.1. I tested this on three different systems.
By: Tilghman Lesher (tilghman) 2009-02-05 13:11:48.000-0600

I just tried it with the setting I pasted above, and it works.  Now, the stream is staticky and bad, but it works in Asterisk.

$ mpg123 --version
mpg123 0.66
By: Tilghman Lesher (tilghman) 2009-02-05 13:25:42.000-0600

and the other half of the problem is that you have specified 'format=ulaw'.  The format is actually 'slin', which is why it sounded staticky.
By: Jonn Taylor (jonnt) 2009-02-05 13:26:11.000-0600

I had that in 1.6.0.3 and then crash in 1.6.0.5. I did have 1.6.0.3 crash too.
By: Jonn Taylor (jonnt) 2009-02-05 13:45:56.000-0600

I have tried it without any format and it does the same thing.
By: Jonn Taylor (jonnt) 2009-02-05 14:14:46.000-0600

Setup test system with 1.6.0.5, MPG123 0.66, CentOS 4.7, FreePBX 2.5.1. Same as production system except that product is CentOS 5.2.

Here is what i got...

[Feb  5 14:05:23] DEBUG[21681] pbx.c: Launching 'MusicOnHold'
[Feb  5 14:05:23] VERBOSE[21681] logger.c:     -- Executing [68742@from-internal:2] MusicOnHold("SIP/4002-086ae668", "default") in new stack
[Feb  5 14:05:23] DEBUG[21681] channel.c: Set channel SIP/4002-086ae668 to write format slin
[Feb  5 14:05:23] VERBOSE[21681] logger.c:     -- Started music on hold, class 'default', on channel 'SIP/4002-086ae668'
[Feb  5 14:05:23] DEBUG[21681] channel.c: Scheduling timer at 160 sample intervals
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Generator got voice, switching to phase locked mode
[Feb  5 14:05:23] DEBUG[21681] channel.c: Scheduling timer at 0 sample intervals
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Internal timing is disabled (option_internal_timing=0 chan->timingfd=34)
[Feb  5 14:05:23] DEBUG[21681] channel.c: Auto-deactivating generator
[Feb  5 14:05:23] DEBUG[21681] channel.c: Set channel SIP/4002-086ae668 to write format ulaw
[Feb  5 14:05:23] VERBOSE[21681] logger.c:     -- Stopped music on hold on SIP/4002-086ae668
[Feb  5 14:05:23] DEBUG[21681] channel.c: Scheduling timer at 0 sample intervals
By: Tilghman Lesher (tilghman) 2009-02-05 14:17:37.000-0600

Well, clearly, you need a timer, as the log messages say you don't have one.  Again, this is a misconfiguration on your part, not an Asterisk bug.
By: Jonn Taylor (jonnt) 2009-02-05 14:18:56.000-0600

dahdi_dummy             8004  0
dahdi_transcode        12808  1 wctc4xxp
dahdi                 195848  15 dahdi_dummy,xpp,dahdi_transcode,wcb4xxp,wctdm,wcfxo,wctdm24xxp,wcte11xp,wct1xxp,wcte12xp,wct4xxp
crc_ccitt               6209  1 dahdi
By: Jonn Taylor (jonnt) 2009-02-05 14:25:36.000-0600

sip*CLI> dahdi show channels
  Chan Extension  Context         Language   MOH Interpret        Blocked    State    
pseudo            default                    default                         In Service
By: Tilghman Lesher (tilghman) 2009-02-05 14:41:39.000-0600

So go into your asterisk.conf, and uncomment the lines "[options]" and "internal_timing = yes", then restart Asterisk.
By: Jonn Taylor (jonnt) 2009-02-05 15:27:10.000-0600

[Feb  5 15:23:36] DEBUG[30965] acl.c: Found IP address for this socket
[Feb  5 15:23:36] WARNING[30965] netsock.c: Unable to set SIP RTP TOS to 184, may be you have no root privileges
[Feb  5 15:23:36] VERBOSE[30965] logger.c:   == Using SIP RTP CoS mark 5
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Setting NAT on RTP to Off
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Allocating new SIP dialog for aswtzhypjvtjwsg@localhost.localdomain - INVITE (With RTP)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Setting NAT on RTP to On
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.173.41:5060
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: = Found Their Call ID: aswtzhypjvtjwsg@localhost.localdomain Their Tag zclnm Our tag: as34e8a04b
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Stopping retransmission on 'aswtzhypjvtjwsg@localhost.localdomain' of Response 312: Match Found
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: = Found Their Call ID: aswtzhypjvtjwsg@localhost.localdomain Their Tag zclnm Our tag: as34e8a04b
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Setting NAT on RTP to On
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Checking SIP call limits for device 4002
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Updating call counter for incoming call
[Feb  5 15:23:36] DEBUG[30965] devicestate.c: Notification of state change to be queued on device/channel SIP/4002
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30937] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: Changing state for SIP/4002 - state 2 (In use)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: *** Our native formats are 0x4 (ulaw)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: *** Joint capabilities are 0xc (ulaw|alaw)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw)
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: This channel will not be able to handle video.
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: build_route: Contact hop: <sip:4002@192.168.254.120>
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: SIP/4002-08b63848: New call is still down.... Trying...
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.173.41:5060
[Feb  5 15:23:36] DEBUG[30965] devicestate.c: Notification of state change to be queued on device/channel SIP/4002
[Feb  5 15:23:36] DEBUG[30939] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30939] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[30969] app_queue.c: Device 'SIP/4002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30937] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: Changing state for SIP/4002 - state 2 (In use)
[Feb  5 15:23:36] DEBUG[31125] pbx.c: Launching 'Answer'
[Feb  5 15:23:36] VERBOSE[31125] logger.c:     -- Executing [68742@from-internal:1] Answer("SIP/4002-08b63848", "") in new stack
[Feb  5 15:23:36] DEBUG[31125] devicestate.c: Notification of state change to be queued on device/channel SIP/4002
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: SIP answering channel: SIP/4002-08b63848
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: Setting framing from config on incoming call
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: True Text flag: True
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: ** Our prefcodec: 0x0 (nothing)
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: -- Done with adding codecs to SDP
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Feb  5 15:23:36] DEBUG[31125] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.173.41:5060
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30937] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[30937] devicestate.c: Changing state for SIP/4002 - state 2 (In use)
[Feb  5 15:23:36] DEBUG[30969] app_queue.c: Device 'SIP/4002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb  5 15:23:36] DEBUG[30969] app_queue.c: Device 'SIP/4002' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Feb  5 15:23:36] DEBUG[30939] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30939] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[30939] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:36] DEBUG[30939] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:36] DEBUG[31125] rtp.c: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.173.41:8001
[Feb  5 15:23:36] DEBUG[31125] rtp.c: Got RTCP report of 48 bytes
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: = Found Their Call ID: aswtzhypjvtjwsg@localhost.localdomain Their Tag zclnm Our tag: as37f0ca44
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Feb  5 15:23:36] DEBUG[30965] chan_sip.c: Stopping retransmission on 'aswtzhypjvtjwsg@localhost.localdomain' of Response 313: Match Found
[Feb  5 15:23:36] DEBUG[31125] rtp.c: RTP NAT: Got audio from other end. Now sending to address 192.168.173.41:8000
[Feb  5 15:23:36] DEBUG[31125] pbx.c: Launching 'MusicOnHold'
[Feb  5 15:23:36] VERBOSE[31125] logger.c:     -- Executing [68742@from-internal:2] MusicOnHold("SIP/4002-08b63848", "default") in new stack
[Feb  5 15:23:36] DEBUG[31125] channel.c: Set channel SIP/4002-08b63848 to write format slin
[Feb  5 15:23:36] VERBOSE[31125] logger.c:     -- Started music on hold, class 'default', on channel 'SIP/4002-08b63848'
[Feb  5 15:23:36] DEBUG[31125] channel.c: Scheduling timer at 160 sample intervals
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=32)
[Feb  5 15:23:36] DEBUG[31125] channel.c: Auto-deactivating generator
[Feb  5 15:23:36] DEBUG[31125] channel.c: Set channel SIP/4002-08b63848 to write format ulaw
[Feb  5 15:23:36] VERBOSE[31125] logger.c:     -- Stopped music on hold on SIP/4002-08b63848
[Feb  5 15:23:36] DEBUG[31125] channel.c: Scheduling timer at 0 sample intervals
[Feb  5 15:23:39] DEBUG[30965] chan_sip.c: = Found Their Call ID: aswtzhypjvtjwsg@localhost.localdomain Their Tag zclnm Our tag: as37f0ca44
[Feb  5 15:23:39] DEBUG[30965] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[Feb  5 15:23:39] DEBUG[30965] chan_sip.c: Setting SIP_ALREADYGONE on dialog aswtzhypjvtjwsg@localhost.localdomain
[Feb  5 15:23:39] DEBUG[30965] chan_sip.c: Received bye, issuing owner hangup
[Feb  5 15:23:39] DEBUG[30965] chan_sip.c: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.173.41:5060
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Spawn extension (from-internal,68742,2) exited non-zero on 'SIP/4002-08b63848'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:   == Spawn extension (from-internal, 68742, 2) exited non-zero on 'SIP/4002-08b63848'
[Feb  5 15:23:39] DEBUG[31125] channel.c: Soft-Hanging up channel 'SIP/4002-08b63848'
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'Macro'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [h@from-internal:1] Macro("SIP/4002-08b63848", "hangupcall") in new stack
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'ResetCDR'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/4002-08b63848", "w") in new stack
[Feb  5 15:23:39] DEBUG[31125] cdr_addon_mysql.c: Inserting a CDR record.
[Feb  5 15:23:39] DEBUG[31125] cdr_addon_mysql.c: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2009-02-05 15:23:36','"device" <4002>','4002','68742','from-internal','SIP/4002-08b63848','','MusicOnHold','default','3','3','ANSWERED','3','','1233869016.0','')
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Executed application: ResetCDR
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'NoCDR'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("SIP/4002-08b63848", "") in new stack
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Executed application: NoCDR
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Expression result is '1'
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'GotoIf'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("SIP/4002-08b63848", "1?skiprg") in new stack
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Goto (macro-hangupcall,s,6)
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Executed application: GotoIf
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Expression result is '1'
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'GotoIf'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("SIP/4002-08b63848", "1?skipblkvm") in new stack
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Goto (macro-hangupcall,s,9)
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Executed application: GotoIf
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Expression result is '1'
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'GotoIf'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("SIP/4002-08b63848", "1?theend") in new stack
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Goto (macro-hangupcall,s,11)
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Executed application: GotoIf
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Launching 'Hangup'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("SIP/4002-08b63848", "") in new stack
[Feb  5 15:23:39] DEBUG[31125] app_macro.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'SIP/4002-08b63848' in macro 'hangupcall'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/4002-08b63848' in macro 'hangupcall'
[Feb  5 15:23:39] DEBUG[31125] pbx.c: Spawn extension (macro-hangupcall,s,11) exited non-zero on 'SIP/4002-08b63848'
[Feb  5 15:23:39] VERBOSE[31125] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'SIP/4002-08b63848'
[Feb  5 15:23:39] DEBUG[31125] channel.c: Hanging up channel 'SIP/4002-08b63848'
[Feb  5 15:23:39] DEBUG[31125] chan_sip.c: Hangup call SIP/4002-08b63848, SIP callid aswtzhypjvtjwsg@localhost.localdomain
[Feb  5 15:23:39] DEBUG[31125] chan_sip.c: Updating call counter for incoming call
[Feb  5 15:23:39] DEBUG[31125] devicestate.c: Notification of state change to be queued on device/channel SIP/4002
[Feb  5 15:23:39] DEBUG[30937] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:39] DEBUG[31125] devicestate.c: Notification of state change to be queued on device/channel SIP/4002
[Feb  5 15:23:39] DEBUG[30937] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:39] DEBUG[30937] devicestate.c: Changing state for SIP/4002 - state 1 (Not in use)
[Feb  5 15:23:39] DEBUG[30937] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:39] DEBUG[30937] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:39] DEBUG[30937] devicestate.c: Changing state for SIP/4002 - state 1 (Not in use)
[Feb  5 15:23:39] DEBUG[30939] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:39] DEBUG[30939] chan_sip.c: Checking device state for peer 4002
[Feb  5 15:23:39] DEBUG[30969] app_queue.c: Device 'SIP/4002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  5 15:23:39] DEBUG[30969] app_queue.c: Device 'SIP/4002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Feb  5 15:23:39] DEBUG[30939] devicestate.c: No provider found, checking channel drivers for SIP - 4002
[Feb  5 15:23:39] DEBUG[30939] chan_sip.c: Checking device state for peer 4002
By: Jonn Taylor (jonnt) 2009-02-08 14:01:30.000-0600

I did more testing and here is what i found. 1.6.0.3 to 1.6.0.5 is broke. 1.6.0.1 and 1.6.0 trunk 174216 works without any problems.

I have also found that if you set internal_timing = yes in asterisk.conf under [options] it is ignored. If you set -I on startup it works.
By: Joshua C. Colp (jcolp) 2009-03-02 14:38:42.000-0600

As mentioned in the last note this issue has been solved. It was caused by revision 153743 which made the failing of a function call fatal, when it was perfectly fine for it to fail when using a stream. The latest code takes this into account so the issue is no longer present.