Asterisk 1.6 Voicemail stopped working

Asterisk Asterisk Support
1

I run Asterisk 1.6.2.24 on a Centos 5.8 machine and it has been working fine for years. The Asterisk install is administered with FreePBX 2.9.0.12. For the various users we have four SIP connections and one PSTN connection (one SIP connection is outbound only). Recently, and I don’t know if it is related to an update or not, inbound callers on our primary (SIP) number are unable to leave a voice mail message. VM works fine for the other connections. The caller hears the unavailable message and the normal beep, this is shortly followed by fast beeps and the call is disconnected. In the log I see this :

[Jul 6 11:11:53] VERBOSE[3942] file.c: – <SIP/xxxxxx-Trunk-00000000> Playing ‘/var/spool/asterisk/voicemail/default/3000/unavail.slin’ (language ‘en’)
[Jul 6 11:11:59] VERBOSE[3942] file.c: – <SIP/xxxxxx-Trunk-00000000> Playing ‘vm-intro.gsm’ (language ‘en’)
[Jul 6 11:12:04] VERBOSE[3942] file.c: – <SIP/xxxxxx-Trunk-00000000> Playing ‘beep.gsm’ (language ‘en’)
[Jul 6 11:12:05] VERBOSE[3942] app_voicemail.c: – Recording the message
[Jul 6 11:12:05] VERBOSE[3942] app.c: – x=0, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/OVq9kt format: wav49, 0xa29a0d8
[Jul 6 11:12:05] VERBOSE[3942] app.c: – x=1, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/OVq9kt format: gsm, 0xa228998
[Jul 6 11:12:05] VERBOSE[3942] app.c: – x=2, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/OVq9kt format: wav, 0xa2bacb8
[Jul 6 11:12:12] WARNING[3942] app.c: No audio available on SIP/xxxxxx-Trunk-00000000??
[Jul 6 11:12:12] VERBOSE[3942] app.c: – User hung up

I am guessing that it is telling me that it can’t find a compatible way to record the message or something?

Asterisk was installed and is kept up to date based on the digium-1.6.2 and digium-current repositories. I recently updated Asterisk from 1.6.2.something (maybe .20?) to 1.6.2.24 but that did not help to resolve this problem.

Any ideas about how to diagnose the cause or resolve this problem?

Thanks, M

2

All that that trace indicates is that, rather unusually, you have asked to record in three formats at one, two of which are essentially the same (wav49 (WAV) and gsm), but nothing but silence has been received.

To get further, I’d suggest using wireshark to see what actually happened at the SIP and RTP levels.

3

What I have done is traced calls incoming over two of our SIP DIDs. The failing one and a working one. Both are directed to ring groups and go to voicemail if not answered. The two lines are configured the same other than their specific provider address and password stuff. They come from different SIP providers. Both use ulaw.

In the working case I see the SIP traffic to set up the call, when the VM kicks in I see RTP traffic in both directions while the message is playing then when recording starts Asterisk stops sending and is only listening. When the caller disconnects recording stops and things appear to be cleaned up nicely.

In the failing case it all looks very similar except that shortly after recording starts Asterisk sends the provider a BYE request and ends the connection. In this it has X-Asterisk-HangupCause: User busy and X-Asterisk-HangupCauseCode: 17.

What might cause this behaviour? I really don’t see any real difference between the configuration of the two lines but recording messages appears to be being rejected by Asterisk.

Any advise or hints would be appreciated.

Thanks!

4

I have also tried swapping ring-groups and mailboxes between the working and the non-working VOIP lines and the problem stays with the original line. So I would conclude that it has something to do with the particular provider or config but I am not seeing what it is.

5

Without the SIP debugging output, neither can we.

6

Hi David,

I truly appreciate your interest & advise with this problem. I am not 100% sure what would be required but I recreated the problem and captured it with Wireshark then filtered the output to only the few frames associated with the connection and edited them to remove anyone’s Personally Identifiable Information (PII). At the start of Wireshark capture there is a quick summary and a legend to show what I have modified in the file to protect PII.

Also I have the verbose output from Asterisk at the time of the failure in case that is useful.

[Jul 8 15:54:18] VERBOSE[20997] pbx.c: -- Executing [s-NOANSWER@macro-vm:2] VoiceMail("SIP/Acanac-Trunk-0000002e", "3000@default,u""") in new stack
[Jul 8 15:54:18] VERBOSE[20997] file.c: -- <SIP/Acanac-Trunk-0000002e> Playing '/var/spool/asterisk/voicemail/default/3000/unavail.slin' (language 'en')
[Jul 8 15:54:27] VERBOSE[20997] file.c: -- <SIP/Acanac-Trunk-0000002e> Playing 'vm-intro.gsm' (language 'en')
[Jul 8 15:54:32] VERBOSE[20997] file.c: -- <SIP/Acanac-Trunk-0000002e> Playing 'beep.gsm' (language 'en')
[Jul 8 15:54:33] VERBOSE[20997] app_voicemail.c: -- Recording the message
[Jul 8 15:54:33] VERBOSE[20997] app.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/G5UKwe format: wav49, 0x87e8ee8
[Jul 8 15:54:33] VERBOSE[20997] app.c: -- x=1, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/G5UKwe format: gsm, 0x863dd70
[Jul 8 15:54:33] VERBOSE[20997] app.c: -- x=2, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/G5UKwe format: wav, 0x8b61490
[Jul 8 15:54:37] WARNING[20997] app.c: No audio available on SIP/Acanac-Trunk-0000002e??
[Jul 8 15:54:37] VERBOSE[20997] app.c: -- User hung up
[Jul 8 15:54:37] VERBOSE[20997] app_macro.c: == Spawn extension (macro-vm, s-NOANSWER, 2) exited non-zero on 'SIP/Acanac-Trunk-0000002e' in macro 'vm'
[Jul 8 15:54:37] VERBOSE[20997] pbx.c: == Spawn extension (ext-local, vmu3000, 1) exited non-zero on 'SIP/Acanac-Trunk-0000002e'
[Jul 8 15:54:37] VERBOSE[20997] pbx.c: -- Executing [h@ext-local:1] Macro("SIP/Acanac-Trunk-0000002e", "hangupcall,") in new stack
[Jul 8 15:54:37] VERBOSE[20997] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Acanac-Trunk-0000002e", "1?theend") in new stack
[Jul 8 15:54:37] VERBOSE[20997] pbx.c: -- Goto (macro-hangupcall,s,3)
[Jul 8 15:54:37] VERBOSE[20997] pbx.c: -- Executing [s@macro-hangupcall:3] Hangup("SIP/Acanac-Trunk-0000002e", "") in new stack

Start  Stop  Dir Description
9844          >  Request:Invite for incomming call
9857         <   Status:Trying
10992        <   Status:Ringing
10993        <   Status:Ringing
10993        <   Status:OK
16797         >  Request:Ack
16799 16918   >  RTP data (from provider only)
16921 23502  <>  RTP data (to and from provider)
23507 23872   >  RTP data (from provider only - recording time?)
25331        <   Request: BYE
25351         >  Status: OK 

Router = Cisco router name
RouterMac = Router MAC address
PCName = PC running Asterisk
PCMAC = PC MAC address
ProviderIP = Provider IP address
CalledNumber = the number that fails to record messages on
CallerNumber = the number that was used to make the call
ExternalIP = the IP address of the building as seen externally
LocalIP = the IP address of the PC running Asterisk

Network

Internet == Modem == Cisco Router == + == NetGear Switch
                                     + == Asterisk PC

No.     Time        Source                Destination           Protocol Info
   9844 67.033061   ProviderIP          LocalIP          SIP/SDP  Request: INVITE sip:CalledNumber@ExternalIP:5060, with session description

Frame 9844 (930 bytes on wire, 930 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Request-Line: INVITE sip:CalledNumber@ExternalIP:5060 SIP/2.0
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK75082009;rport
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>
        Contact: <sip:CallerNumber@ProviderIP:5060>
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 INVITE
        User-Agent: Asterisk PBX
        Max-Forwards: 70
        Remote-Party-ID: "CallerNumber" <sip:CallerNumber@ProviderIP>;privacy=off;screen=no
        Date: Sun, 08 Jul 2012 19:54:00 GMT
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
        Supported: replaces
        Content-Type: application/sdp
        Content-Length: 238
    Message Body
        Session Description Protocol
            Session Description Protocol Version (v): 0
            Owner/Creator, Session Id (o): root 6871 6871 IN IP4 ProviderIP
            Session Name (s): session
            Connection Information (c): IN IP4 ProviderIP
            Time Description, active time (t): 0 0
            Media Description, name and address (m): audio 17156 RTP/AVP 0 101
            Media Attribute (a): rtpmap:0 PCMU/8000
            Media Attribute (a): rtpmap:101 telephone-event/8000
            Media Attribute (a): fmtp:101 0-16
            Media Attribute (a): silenceSupp:off - - - -
            Media Attribute (a): ptime:20
            Media Attribute (a): sendrecv

No.     Time        Source                Destination           Protocol Info
   9857 67.036684   LocalIP          ProviderIP          SIP      Status: 100 Trying

Frame 9857 (519 bytes on wire, 519 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 100 Trying
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK75082009;received=ProviderIP;rport=5060
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 INVITE
        Server: asterisk
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Contact: <sip:CalledNumber@LocalIP>
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  10992 68.197570   LocalIP          ProviderIP          SIP      Status: 180 Ringing

Frame 10992 (535 bytes on wire, 535 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 180 Ringing
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK75082009;received=ProviderIP;rport=5060
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 INVITE
        Server: asterisk
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Contact: <sip:CalledNumber@LocalIP>
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  10993 68.198132   LocalIP          ProviderIP          SIP      Status: 180 Ringing

Frame 10993 (535 bytes on wire, 535 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 180 Ringing
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK75082009;received=ProviderIP;rport=5060
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 INVITE
        Server: asterisk
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Contact: <sip:CalledNumber@LocalIP>
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  16749 83.768042   LocalIP          ProviderIP          SIP/SDP  Status: 200 OK, with session description

Frame 16749 (742 bytes on wire, 742 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 200 OK
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK75082009;received=ProviderIP;rport=5060
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 INVITE
        Server: asterisk
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Contact: <sip:CalledNumber@LocalIP>
        Content-Type: application/sdp
        Content-Length: 179
    Message Body
        Session Description Protocol
            Session Description Protocol Version (v): 0
            Owner/Creator, Session Id (o): root 680470532 680470532 IN IP4 LocalIP
            Session Name (s): Asterisk PBX 1.6.2.24
            Connection Information (c): IN IP4 LocalIP
            Time Description, active time (t): 0 0
            Media Description, name and address (m): audio 11554 RTP/AVP 0
            Media Attribute (a): rtpmap:0 PCMU/8000
            Media Attribute (a): ptime:20
            Media Attribute (a): sendrecv

No.     Time        Source                Destination           Protocol Info
  16797 83.845901   ProviderIP          LocalIP          SIP      Request: ACK sip:CalledNumber@ExternalIP:5060

Frame 16797 (542 bytes on wire, 542 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Request-Line: ACK sip:CalledNumber@ExternalIP:5060 SIP/2.0
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK3add9eca;rport
        From: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        To: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        Contact: <sip:CallerNumber@ProviderIP:5060>
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 ACK
        User-Agent: Asterisk PBX
        Max-Forwards: 70
        Remote-Party-ID: "CallerNumber" <sip:CallerNumber@ProviderIP>;privacy=off;screen=no
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  16799 83.848573   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=48459, Time=135424, Mark 

Frame 16799 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    1... .... = Marker: True
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 48459
    [Extended sequence number: 48459]
    Timestamp: 135424
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7EFF7EFEFDFBFAFDFDFF7E7C7C7C7CFE7E7E7E7F7FFEFDFE...


<<<<<<<<<<<<<<<<<<frames removed>>>>>>>>>>>>>>>>>>>>


No.     Time        Source                Destination           Protocol Info
  16913 84.254008   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=48480, Time=138784 

Frame 16913 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 48480
    [Extended sequence number: 48480]
    Timestamp: 138784
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7DFF7B7F7A79FEFFF4FFFA7AFFF97BFE727D7DF8F5FFF7FE...

No.     Time        Source                Destination           Protocol Info
  16918 84.269937   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=48481, Time=138944 

Frame 16918 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 48481
    [Extended sequence number: 48481]
    Timestamp: 138944
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7F73FCF9FCFB78F979FC7D7CFD75FE76FD7EFBFB757D7AF4...

No.     Time        Source                Destination           Protocol Info
  16921 84.282322   LocalIP          ProviderIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x4506FF02, Seq=14445, Time=160, Mark 

Frame 16921 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: 11554 (11554), Dst Port: 17156 (17156)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 9844)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    1... .... = Marker: True
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 14445
    [Extended sequence number: 79981]
    Timestamp: 160
    Synchronization Source identifier: 0x4506ff02 (1158086402)
    Payload: FFFFFFFFFFFFFF7E7E7E7E7E7E7E7EFF7E7E7E7E7E7E7E7E...

No.     Time        Source                Destination           Protocol Info
  16922 84.289489   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=48482, Time=139104 

<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<Frames Removed>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

No.     Time        Source                Destination           Protocol Info
  23501 98.512196   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=49193, Time=252864 

Frame 23501 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 49193
    [Extended sequence number: 49193]
    Timestamp: 252864
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7FFFFF7FFF7F7F7F7F7F7F7F7FFFFFFFFFFF7F7F7F7F7FFF...

No.     Time        Source                Destination           Protocol Info
  23502 98.515618   LocalIP          ProviderIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x4506FF02, Seq=15150, Time=113760 

Frame 23502 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: 11554 (11554), Dst Port: 17156 (17156)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 9844)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 15150
    [Extended sequence number: 80686]
    Timestamp: 113760
    Synchronization Source identifier: 0x4506ff02 (1158086402)
    Payload: C24B312B2B3351BEAEAAADB972382D2B2F42CDB4ADADB4CC...

No.     Time        Source                Destination           Protocol Info
  23507 98.540931   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=49194, Time=253024 

Frame 23507 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 49194
    [Extended sequence number: 49194]
    Timestamp: 253024
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7FFFFFFFFFFFFFFFFF7F7F7FFF7F7FFF7F7F7F7F7FFFFFFF...

No.     Time        Source                Destination           Protocol Info
  23512 98.552922   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=49195, Time=253184 

Frame 23512 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 49195
    [Extended sequence number: 49195]
    Timestamp: 253184
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7FFFFFFFFFFFFF7F7FFFFF7F7FFFFFFFFFFFFFFFFFFFFFFF...

<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<Frames Removed>>>>>>>>>>>>>>>>>>>>>>>>>>

No.     Time        Source                Destination           Protocol Info
  23867 99.311168   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=49233, Time=259264 

Frame 23867 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 49233
    [Extended sequence number: 49233]
    Timestamp: 259264
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: FE7FFBFCFEFFFEF9FAFBFD7E7EFC7D7E7DFDFE7B7A797E7D...

No.     Time        Source                Destination           Protocol Info
  23872 99.333069   ProviderIP          LocalIP          RTP      PT=ITU-T G.711 PCMU, SSRC=0x5B0ACDC4, Seq=49234, Time=259424 

Frame 23872 (214 bytes on wire, 214 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: 17156 (17156), Dst Port: 11554 (11554)
Real-Time Transport Protocol
    [Stream setup by SDP (frame 16749)]
    10.. .... = Version: RFC 1889 Version (2)
    ..0. .... = Padding: False
    ...0 .... = Extension: False
    .... 0000 = Contributing source identifiers count: 0
    0... .... = Marker: False
    Payload type: ITU-T G.711 PCMU (0)
    Sequence number: 49234
    [Extended sequence number: 49234]
    Timestamp: 259424
    Synchronization Source identifier: 0x5b0acdc4 (1527434692)
    Payload: 7C7D7CFFFFFDFCFFFDFDFDFE7C7E7C7C7B7F7DFEFE7EFEFC...

No.     Time        Source                Destination           Protocol Info
  25331 103.335446  LocalIP          ProviderIP          SIP      Request: BYE sip:CallerNumber@ProviderIP:5060

Frame 25331 (477 bytes on wire, 477 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Request-Line: BYE sip:CallerNumber@ProviderIP:5060 SIP/2.0
    Message Header
        Via: SIP/2.0/UDP LocalIP:5060;branch=z9hG4bK0c9e8a32;rport
        Max-Forwards: 70
        From: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        To: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 BYE
        User-Agent: asterisk
        X-Asterisk-HangupCause: User busy
        X-Asterisk-HangupCauseCode: 17
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  25351 103.386354  ProviderIP          LocalIP          SIP      Status: 200 OK

Frame 25351 (482 bytes on wire, 482 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 200 OK
    Message Header
        Via: SIP/2.0/UDP LocalIP:5060;branch=z9hG4bK0c9e8a32;received=ExternalIP;rport=5060
        From: <sip:CalledNumber@LocalIP:5060>;tag=as669b08e7
        To: "CallerNumber" <sip:CallerNumber@ProviderIP:5060>;tag=as58520554
        Call-ID: 7a6f9dcb25a3175f7394f9213cc3692d@ProviderIP
        CSeq: 102 BYE
        User-Agent: Asterisk PBX
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
        Supported: replaces
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  30556 124.536731  ProviderIP          LocalIP          SIP      Request: OPTIONS sip:CalledNumber@ExternalIP:5060

Frame 30556 (572 bytes on wire, 572 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Request-Line: OPTIONS sip:CalledNumber@ExternalIP:5060 SIP/2.0
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK76532487;rport
        From: "asterisk" <sip:asterisk@ProviderIP:5060>;tag=as23666a77
        To: <sip:CalledNumber@LocalIP:5060>
        Contact: <sip:asterisk@ProviderIP:5060>
        Call-ID: 6b2eac016ebc467610f3bcaf5a73d5db@ProviderIP
        CSeq: 102 OPTIONS
        User-Agent: Asterisk PBX
        Max-Forwards: 70
        Date: Sun, 08 Jul 2012 19:54:58 GMT
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
        Supported: replaces
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  30557 124.537236  LocalIP          ProviderIP          SIP      Status: 200 OK

Frame 30557 (541 bytes on wire, 541 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 200 OK
    Message Header
        Via: SIP/2.0/UDP ProviderIP:5060;branch=z9hG4bK76532487;received=ProviderIP;rport=5060
        From: "asterisk" <sip:asterisk@ProviderIP:5060>;tag=as23666a77
        To: <sip:CalledNumber@LocalIP:5060>;tag=as4d64b48b
        Call-ID: 6b2eac016ebc467610f3bcaf5a73d5db@ProviderIP
        CSeq: 102 OPTIONS
        Server: asterisk
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Contact: <sip:LocalIP>
        Accept: application/sdp
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  33985 145.539872  LocalIP          ProviderIP          SIP      Request: OPTIONS sip:ProviderIP

Frame 33985 (536 bytes on wire, 536 bytes captured)
Ethernet II, Src: PCName (00:PCMAC), Dst: Router.local (RouterMAC)
Internet Protocol, Src: LocalIP (LocalIP), Dst: ProviderIP (ProviderIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Request-Line: OPTIONS sip:ProviderIP SIP/2.0
    Message Header
        Via: SIP/2.0/UDP LocalIP:5060;branch=z9hG4bK77384e4f;rport
        Max-Forwards: 70
        From: "Unknown" <sip:Unknown@LocalIP>;tag=as540d4ff0
        To: <sip:ProviderIP>
        Contact: <sip:Unknown@LocalIP>
        Call-ID: 05c72dc16fceb7534e4bd15d44fd62a3@LocalIP
        CSeq: 102 OPTIONS
        User-Agent: asterisk
        Date: Sun, 08 Jul 2012 19:55:20 GMT
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
        Supported: replaces, timer
        Content-Length: 0

No.     Time        Source                Destination           Protocol Info
  33988 145.621789  ProviderIP          LocalIP          SIP      Status: 404 Not Found

Frame 33988 (496 bytes on wire, 496 bytes captured)
Ethernet II, Src: Router.local (RouterMAC), Dst: PCName (00:PCMAC)
Internet Protocol, Src: ProviderIP (ProviderIP), Dst: LocalIP (LocalIP)
User Datagram Protocol, Src Port: sip (5060), Dst Port: sip (5060)
Session Initiation Protocol
    Status-Line: SIP/2.0 404 Not Found
    Message Header
        Via: SIP/2.0/UDP LocalIP:5060;branch=z9hG4bK77384e4f;received=ExternalIP;rport=5060
        From: "Unknown" <sip:Unknown@LocalIP:5060>;tag=as540d4ff0
        To: <sip:ProviderIP>;tag=as1b1b8c9f
        Call-ID: 05c72dc16fceb7534e4bd15d44fd62a3@LocalIP
        CSeq: 102 OPTIONS
        User-Agent: Asterisk PBX
        Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
        Supported: replaces
        Accept: application/sdp
        Content-Length: 0

Advise and suggestions about how to resolve this greatly appreciated

7

One of the reasons I said wireshark, rather than Asterisk’s sip debugging, is that you can listen to the media streams. Asterisk is behaving as though it heard silence, so you need to confirm whether there was actually any audio.

8

OK, I will investigate that. Right now I have been connecting remotely with SSH to the machine so I expect that I will need to be at the machine itself and connect some speakers to listen to steams there. Normal calls work just fine with audio in both directions, it is just the voicemail recording that seems to be failing.

Thanks, M

9

I spent some time today to investigate how to convert RTP streams into audio and found out that the version of Wireshark on the machine must be downlevel or something as it does not appear to have the feature. However. in tracing this again with Wireshark and looking at the Asterisk logs I did notice something that I have overlooked before.

Something that I see occasionally in the Asterisk logs is NOTICE messages about “Unknown RTP codec 72”. But since there have been no problems from it I have ignored them. In the last couple of tests that I did with this message recording problem I find that sometimes part of the message is recorded from about 3 to 10 or so seconds. In those cases I see that rtp.c reports the unknown codec message. So then I captured it with Wireshark. What I see is a spurious (out of sequence) RTP packet with a Packet Type of 72 from the provider. The bad packet is in the stream in time sequence but it’s sequence number is wrong and SSRC value is not the same as “good” packets. These bad RTP packets don’t seem to (noticeably) affect normal connections but are not handled well when recording a message.

My thought is that if one is received when Asterisk is checking for an audio stream before recording a message it terminates the call right away (no message recorded) but if it is received during the message recording it will record up to that point. I am pursuing the cause of these packets with the VOIP provider but I would like to somehow configure Asterisk to ignore these bad packets. Is that possible?

M

[Jul 10 19:06:34] VERBOSE[11790] file.c: -- <SIP/Provider-Trunk-00000017> Playing '/var/spool/asterisk/voicemail/default/3000/unavail.slin' (language 'en')
[Jul 10 19:06:39] NOTICE[11790] rtp.c: Unknown RTP codec 72 received from 'ProviderIP'
[Jul 10 19:06:42] VERBOSE[11790] file.c: -- <SIP/Provider-Trunk-00000017> Playing 'vm-intro.gsm' (language 'en')
[Jul 10 19:06:44] NOTICE[11790] rtp.c: Unknown RTP codec 72 received from 'ProviderIP'
[Jul 10 19:06:47] VERBOSE[11790] file.c: -- <SIP/Provider-Trunk-00000017> Playing 'beep.gsm' (language 'en')
[Jul 10 19:06:48] VERBOSE[11790] app_voicemail.c: -- Recording the message
[Jul 10 19:06:48] VERBOSE[11790] app.c: -- x=0, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/Jg8uo4 format: wav49, 0x8c68b98
[Jul 10 19:06:48] VERBOSE[11790] app.c: -- x=1, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/Jg8uo4 format: gsm, 0x8c67870
[Jul 10 19:06:48] VERBOSE[11790] app.c: -- x=2, open writing: /var/spool/asterisk/voicemail/default/3000/tmp/Jg8uo4 format: wav, 0x8c6c270
[Jul 10 19:06:49] NOTICE[11790] rtp.c: Unknown RTP codec 72 received from 'ProviderIP'
[Jul 10 19:06:53] WARNING[11790] app.c: No audio available on SIP/Provider-Trunk-00000017??
[Jul 10 19:06:53] VERBOSE[11790] app.c: -- User hung up
10

I opened a ticket with the VOIP provider and they seem to have done something that resolved the problem. However, I think it would be good if Asterisk could simply ignore the spurious out of sync packets rather than trying to handle them and ending up with a bad result.

M