[Asterisk-Users] Help with this debug output?

[Chris TenHarmsel]

Hi all,
I've attached the output from asterisk with "set verbose 3".  During
the time in the file, I placed two calls with my Zyxel 2000w to a
Cisco 7912g.  The first call worked fine, I was able to talk to the
person on the other phone.  The second call went through and rung the
7912g, but I was unable to hear the other person, and they could not
hear me.  This continues until I reset the 2000w, at which time, one
call works again.

Any ideas from this output as to why this is happening?

-Chris
-------------- next part --------------
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:5397 check_user_full: Setting NAT on RTP to 0
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:5401 check_user_full: Setting NAT on VRTP to 0
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:7227 handle_request: Check for res for wireless1
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:1671 update_user_counter: Call from user 'wireless1' is 1 out of 0
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:4612 build_route: build_route: Contact hop: <sip:wireless1 at 10.1.1.195:5060;transport=udp>
    -- Executing Macro("SIP/wireless1-9409", "stdexten|1000|SIP/cluster2") in new stack
    -- Executing Dial("SIP/wireless1-9409", "SIP/cluster2|20") in new stack
Nov 15 12:33:01 DEBUG[25615]: chan_sip.c:1297 create_addr: Setting NAT on RTP to 0
Nov 15 12:33:01 DEBUG[25615]: chan_sip.c:1301 create_addr: Setting NAT on VRTP to 0
Nov 15 12:33:01 DEBUG[25615]: chan_sip.c:1538 sip_call: Outgoing Call for cluster2
Nov 15 12:33:01 DEBUG[25615]: chan_sip.c:1671 update_user_counter: Call from user 'cluster2' is 1 out of 0
    -- Called cluster2
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:860 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7be5848734bfff4218b8ef9f5241be9f at 10.1.1.103' Request 102: Found
Nov 15 12:33:01 DEBUG[6150]: chan_sip.c:860 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7be5848734bfff4218b8ef9f5241be9f at 10.1.1.103' Request 102: Found
    -- SIP/cluster2-d469 is ringing
Nov 15 12:33:02 DEBUG[6150]: chan_sip.c:810 __sip_ack: Acked pending invite 102
Nov 15 12:33:02 DEBUG[6150]: chan_sip.c:828 __sip_ack: Stopping retransmission on '7be5848734bfff4218b8ef9f5241be9f at 10.1.1.103' of Request 102: Found
Nov 15 12:33:02 DEBUG[6150]: chan_sip.c:4612 build_route: build_route: Contact hop: <sip:cluster2 at 10.1.1.198:5060;transport=udp>
    -- SIP/cluster2-d469 answered SIP/wireless1-9409
    -- Attempting native bridge of SIP/wireless1-9409 and SIP/cluster2-d469
Nov 15 12:33:02 DEBUG[25615]: rtp.c:1175 ast_rtp_write: Ooh, format changed from UNKN to ULAW
Nov 15 12:33:03 DEBUG[6150]: chan_sip.c:828 __sip_ack: Stopping retransmission on '45389-1B12-12D4-C82D-D88FAFD86A3E at 10.1.1.195' of Response 1: Found
Nov 15 12:33:03 DEBUG[25615]: rtp.c:1175 ast_rtp_write: Ooh, format changed from UNKN to ULAW
Nov 15 12:33:08 DEBUG[25615]: rtp.c:190 send_dtmf: Sending dtmf: 51 (3), at 10.1.1.195
Nov 15 12:33:08 DEBUG[25615]: channel.c:1128 ast_settimeout: Scheduling timer at 160 sample intervals
Nov 15 12:33:08 DEBUG[25615]: channel.c:1379 ast_read: Generator got voice, switching to phase locked mode
Nov 15 12:33:08 DEBUG[25615]: channel.c:1128 ast_settimeout: Scheduling timer at 0 sample intervals
Nov 15 12:33:09 DEBUG[25615]: channel.c:1388 ast_read: Auto-deactivating generator
Nov 15 12:33:09 DEBUG[25615]: channel.c:1128 ast_settimeout: Scheduling timer at 0 sample intervals
Nov 15 12:33:09 DEBUG[25615]: channel.c:2655 ast_channel_bridge: Didn't get a frame from channel: SIP/wireless1-9409
Nov 15 12:33:09 DEBUG[25615]: channel.c:2725 ast_channel_bridge: Bridge stops bridging channels SIP/wireless1-9409 and SIP/cluster2-d469
Nov 15 12:33:09 DEBUG[25615]: chan_sip.c:1767 sip_hangup: update_user_counter(cluster2) - decrement outUse counter
Nov 15 12:33:09 DEBUG[25615]: app_dial.c:1029 dial_exec: Exiting with DIALSTATUS=ANSWER.
  == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'SIP/wireless1-9409' in macro 'stdexten'
  == Spawn extension (default-local-sip, 1003, 1) exited non-zero on 'SIP/wireless1-9409'
Nov 15 12:33:09 DEBUG[25615]: chan_sip.c:1770 sip_hangup: update_user_counter(wireless1) - decrement inUse counter
Nov 15 12:33:09 DEBUG[6150]: chan_sip.c:828 __sip_ack: Stopping retransmission on '7be5848734bfff4218b8ef9f5241be9f at 10.1.1.103' of Request 103: Found
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:5397 check_user_full: Setting NAT on RTP to 0
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:5401 check_user_full: Setting NAT on VRTP to 0
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:7227 handle_request: Check for res for wireless1
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:1671 update_user_counter: Call from user 'wireless1' is 1 out of 0
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:4612 build_route: build_route: Contact hop: <sip:wireless1 at 10.1.1.195:5060;transport=udp>
    -- Executing Macro("SIP/wireless1-d807", "stdexten|1000|SIP/cluster2") in new stack
    -- Executing Dial("SIP/wireless1-d807", "SIP/cluster2|20") in new stack
Nov 15 12:33:16 DEBUG[26639]: chan_sip.c:1297 create_addr: Setting NAT on RTP to 0
Nov 15 12:33:16 DEBUG[26639]: chan_sip.c:1301 create_addr: Setting NAT on VRTP to 0
Nov 15 12:33:16 DEBUG[26639]: chan_sip.c:1538 sip_call: Outgoing Call for cluster2
Nov 15 12:33:16 DEBUG[26639]: chan_sip.c:1671 update_user_counter: Call from user 'cluster2' is 1 out of 0
    -- Called cluster2
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:860 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '00581bca08788e294036513e7e85619a at 10.1.1.103' Request 102: Found
Nov 15 12:33:16 DEBUG[6150]: chan_sip.c:860 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '00581bca08788e294036513e7e85619a at 10.1.1.103' Request 102: Found
    -- SIP/cluster2-c5cf is ringing
Nov 15 12:33:17 DEBUG[6150]: chan_sip.c:810 __sip_ack: Acked pending invite 102
Nov 15 12:33:17 DEBUG[6150]: chan_sip.c:828 __sip_ack: Stopping retransmission on '00581bca08788e294036513e7e85619a at 10.1.1.103' of Request 102: Found
Nov 15 12:33:17 DEBUG[6150]: chan_sip.c:4612 build_route: build_route: Contact hop: <sip:cluster2 at 10.1.1.198:5060;transport=udp>
    -- SIP/cluster2-c5cf answered SIP/wireless1-d807
    -- Attempting native bridge of SIP/wireless1-d807 and SIP/cluster2-c5cf
Nov 15 12:33:17 DEBUG[26639]: rtp.c:1175 ast_rtp_write: Ooh, format changed from UNKN to ULAW
Nov 15 12:33:20 DEBUG[26639]: channel.c:2655 ast_channel_bridge: Didn't get a frame from channel: SIP/wireless1-d807
Nov 15 12:33:20 DEBUG[26639]: channel.c:2725 ast_channel_bridge: Bridge stops bridging channels SIP/wireless1-d807 and SIP/cluster2-c5cf
Nov 15 12:33:20 DEBUG[26639]: chan_sip.c:1767 sip_hangup: update_user_counter(cluster2) - decrement outUse counter
Nov 15 12:33:20 DEBUG[26639]: app_dial.c:1029 dial_exec: Exiting with DIALSTATUS=ANSWER.
  == Spawn extension (macro-stdexten, s, 1) exited non-zero on 'SIP/wireless1-d807' in macro 'stdexten'
  == Spawn extension (default-local-sip, 1003, 1) exited non-zero on 'SIP/wireless1-d807'
Nov 15 12:33:20 DEBUG[26639]: chan_sip.c:1770 sip_hangup: update_user_counter(wireless1) - decrement inUse counter
Nov 15 12:33:20 DEBUG[6150]: chan_sip.c:828 __sip_ack: Stopping retransmission on '00581bca08788e294036513e7e85619a at 10.1.1.103' of Request 103: Found
Nov 15 12:33:22 DEBUG[8200]: chan_iax2.c:5787 socket_read: Immediately destroying 1, having received INVA