[Freeswitch-users] Openzap: every second incoming call fails
Michael S Collins
msc at freeswitch.org
Fri Jan 9 12:40:48 PST 2009
:)
Sent from my iPhone
On Jan 9, 2009, at 7:38 AM, Peter P GMX <Prometheus001 at gmx.net> wrote:
> Hello Michael,
>
> sorry for the inconvenience. It turned out that our Telco had to reset
> the second PRI line. Now it works.
>
> Best regards
> Peter
>
> Peter P GMX schrieb:
>> Hello Michael,
>>
>> here is a log of 2 calls. The first is one successfull, the second
>> not.
>>
>> Bestr regards
>> Peter
>>
>> 2009-01-08 17:57:29 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[5a] Size:[103] CRV: 16 (0x10, CTX: Originator)
>> 2009-01-08 17:57:29 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x10]
>> 2009-01-08 17:57:29 [DEBUG] ozmod_isdn.c:418 zap_isdn_931_34()
>> Changing
>> state on 1:1 from TERMINATING to DOWN
>> 2009-01-08 17:57:29 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [DOWN]
>> 2009-01-08 17:57:29 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:57:45 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 40
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 45 05 04 03 80 90 a3 18 03 a1 83 81 6c 0c 21 81 36 39 33
>> 34 34
>> 30 39 32 30 30 70 09 c1 32 31 36 35 38 35 31 39]
>>
>> 2009-01-08 17:57:45 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[05] Size:[179] CRV: 69 (0x45, CTX: Originator)
>> 2009-01-08 17:57:45 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x45]
>> 2009-01-08 17:57:45 [WARNING] ozmod_isdn.c:572 zap_isdn_931_34()
>> Channel
>> 2:1 ~ 2:32 is already in use waiting for it to become available.
>> 2009-01-08 17:57:46 [ERR] ozmod_isdn.c:586 zap_isdn_931_34()
>> Channel 2:1
>> ~ 2:32 is already in use.
>> 2009-01-08 17:57:46 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 9
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 45 45 08 02 81 e5]
>>
>> 2009-01-08 17:57:46 [CRIT] ozmod_isdn.c:644 zap_isdn_931_34()
>> Failed to
>> open channel for new setup message
>> 2009-01-08 17:57:47 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 45 4d]
>>
>> 2009-01-08 17:57:47 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[4d] Size:[103] CRV: 69 (0x45, CTX: Originator)
>> 2009-01-08 17:57:47 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x45]
>> 2009-01-08 17:57:47 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>> Received
>> Release with no matching channel 0
>> 2009-01-08 17:57:47 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23() 931
>> parse
>> error [-3012] [Q931E_INVALID_CRV]
>> 2009-01-08 17:57:51 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 45 4d]
>>
>> 2009-01-08 17:57:51 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[4d] Size:[103] CRV: 69 (0x45, CTX: Originator)
>> 2009-01-08 17:57:51 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x45]
>> 2009-01-08 17:57:51 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>> Received
>> Release with no matching channel 0
>> 2009-01-08 17:57:51 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23() 931
>> parse
>> error [-3012] [Q931E_INVALID_CRV]
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 40
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 05 04 03 80 90 a3 18 03 a1 83 81 6c 0c 21 81 36 39 33
>> 34 34
>> 30 39 32 30 30 70 09 c1 32 31 36 35 38 35 31 39]
>>
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[05] Size:[179] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:690 zap_isdn_931_34()
>> Changing
>> state on 1:1 from DOWN to RING
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [RING]
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:1418
>> on_clear_channel_signal()
>> got clear channel sig [START]
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:340 tech_init() Set codec
>> PCMA
>> 20ms
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:1125
>> zap_channel_from_event()
>> Connect inbound channel OpenZAP/1:1/21658519
>> 2009-01-08 17:58:10 [NOTICE] switch_channel.c:565
>> switch_channel_set_name() New Channel OpenZAP/1:1/21658519
>> [87c6dbc8-dda5-11dd-9836-2fb1a1f66971]
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:1129
>> zap_channel_from_event()
>> (OpenZAP/1:1/21658519) State Change CS_NEW -> CS_INIT
>> 2009-01-08 17:58:10 [DEBUG] switch_core_session.c:807
>> switch_core_session_signal_state_change() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:379
>> switch_core_session_run() (OpenZAP/1:1/21658519) Running State Change
>> CS_INIT
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:444
>> switch_core_session_run() (OpenZAP/1:1/21658519) State INIT
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:364 channel_on_init()
>> (OpenZAP/1:1/21658519) State Change CS_INIT -> CS_ROUTING
>> 2009-01-08 17:58:10 [DEBUG] switch_core_session.c:807
>> switch_core_session_signal_state_change() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:444
>> switch_core_session_run() (OpenZAP/1:1/21658519) State INIT going
>> to sleep
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:379
>> switch_core_session_run() (OpenZAP/1:1/21658519) Running State Change
>> CS_ROUTING
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:447
>> switch_core_session_run() (OpenZAP/1:1/21658519) State ROUTING
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:387 channel_on_routing()
>> OpenZAP/1:1/21658519 CHANNEL ROUTING
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:64
>> switch_core_standard_on_routing() OpenZAP/1:1/21658519 Standard
>> ROUTING
>> 2009-01-08 17:58:10 [INFO] mod_dialplan_xml.c:233 dialplan_hunt()
>> Processing 6934409200->21658519 in context default
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_test-caller] destination_number(21658519) =~ /^(50[0-9]
>> [0-9])/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_inform_hangup] destination_number(21658519) =~ /8888/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_error_inform_hangup] destination_number(21658519) =~ /8887/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [park position] destination_number(21658519) =~ /8886/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_test_consultant] destination_number(21658519) =~ /5002/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_rejump into state machine] destination_number(21658519)
>> =~ /5004/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [liverpie_test-caller_56] destination_number(21658519) =~ /5056/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [nb_conferencesfrom external] destination_number(21658519) =~ /
>> ^(21658599)$/
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:119 parse_exten()
>> Regex
>> mismatch
>> 2009-01-08 17:58:10 [DEBUG] mod_dialplan_xml.c:117 parse_exten()
>> Regex:
>> [Inbound Zaptel] destination_number(21658519) =~ /^(216585[0-9]+)$/
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:100
>> switch_core_standard_on_routing() (OpenZAP/1:1/21658519) State Change
>> CS_ROUTING -> CS_EXECUTE
>> 2009-01-08 17:58:10 [DEBUG] switch_core_session.c:807
>> switch_core_session_signal_state_change() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:447
>> switch_core_session_run() (OpenZAP/1:1/21658519) State ROUTING
>> going to
>> sleep
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:379
>> switch_core_session_run() (OpenZAP/1:1/21658519) Running State Change
>> CS_EXECUTE
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:454
>> switch_core_session_run() (OpenZAP/1:1/21658519) State EXECUTE
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:404 channel_on_execute()
>> OpenZAP/1:1/21658519 CHANNEL EXECUTE
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:137
>> switch_core_standard_on_execute() OpenZAP/1:1/21658519 Standard
>> EXECUTE
>> 2009-01-08 17:58:10 [DEBUG] switch_core_state_machine.c:152
>> switch_core_standard_on_execute() OpenZAP/1:1/21658519 Execute
>> answer()
>> 2009-01-08 17:58:10 [DEBUG] mod_dptools.c:600 answer_function()
>> OpenZAP/1:1/21658519 receive message [ANSWER]
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:750
>> channel_receive_message_b() Changing state on 1:1 from RING to
>> PROGRESS
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [PROGRESS]
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 15
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 11 02 04 03 80 90 a3 18 03 a1 83 81]
>>
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:753
>> channel_receive_message_b() Changing state on 1:1 from PROGRESS to
>> PROGRESS_MEDIA
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [PROGRESS_MEDIA]
>> 2009-01-08 17:58:10 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 15
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 11 01 04 03 80 90 a3 18 03 a1 83 81]
>>
>> 2009-01-08 17:58:10 [DEBUG] mod_openzap.c:755
>> channel_receive_message_b() Changing state on 1:1 from
>> PROGRESS_MEDIA to UP
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE [UP]
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 10
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 11 07 18 03 a1 83 81]
>>
>> 2009-01-08 17:58:11 [DEBUG] switch_core_session.c:511
>> switch_core_session_perform_receive_message() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:11 [NOTICE] mod_dptools.c:600 answer_function()
>> Channel
>> [OpenZAP/1:1/21658519] has been answered
>> 2009-01-08 17:58:11 [DEBUG] switch_channel.c:177
>> switch_channel_audio_sync() OpenZAP/1:1/21658519 receive message
>> [AUDIO_SYNC]
>> 2009-01-08 17:58:11 [DEBUG] switch_core_state_machine.c:152
>> switch_core_standard_on_execute() OpenZAP/1:1/21658519 Execute
>> export(service_number=true)
>> 2009-01-08 17:58:11 [DEBUG] mod_dptools.c:837 export_function()
>> EXPORT
>> [service_number]=[true]
>> 2009-01-08 17:58:11 [DEBUG] switch_core_state_machine.c:152
>> switch_core_standard_on_execute() OpenZAP/1:1/21658519 Execute
>> export(sip_secure_media=false)
>> 2009-01-08 17:58:11 [DEBUG] mod_dptools.c:837 export_function()
>> EXPORT
>> [sip_secure_media]=[false]
>> 2009-01-08 17:58:11 [DEBUG] switch_core_state_machine.c:152
>> switch_core_standard_on_execute() OpenZAP/1:1/21658519 Execute
>> socket(127.0.0.1:8085 async full)
>> 2009-01-08 17:58:11 [DEBUG] mod_event_socket.c:1797 listener_run()
>> Connection Open
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 14
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 7d 08 04 82 e3 98 04 14 01 09]
>>
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[7d] Size:[114] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:11 [CRIT] ozmod_isdn.c:760 zap_isdn_931_34()
>> Received
>> unhandled message 125 (0x7d)
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 14
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 7d 08 04 82 e3 98 04 14 01 07]
>>
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[7d] Size:[114] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:11 [CRIT] ozmod_isdn.c:760 zap_isdn_931_34()
>> Received
>> unhandled message 125 (0x7d)
>> 2009-01-08 17:58:11 [DEBUG] switch_core_session.c:694
>> switch_core_session_queue_private_event() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:11 [DEBUG] switch_channel.c:177
>> switch_channel_audio_sync() OpenZAP/1:1/21658519 receive message
>> [AUDIO_SYNC]
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 0f]
>>
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[0f] Size:[103] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:11 [DEBUG] ozmod_isdn.c:709 zap_isdn_931_34()
>> Received
>> CONNECT_ACK message for channel 0
>> 2009-01-08 17:58:11 [DEBUG] switch_core_session.c:694
>> switch_core_session_queue_private_event() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:11 [DEBUG] switch_channel.c:177
>> switch_channel_audio_sync() OpenZAP/1:1/21658519 receive message
>> [AUDIO_SYNC]
>> 2009-01-08 17:58:11 [DEBUG] switch_core_session.c:694
>> switch_core_session_queue_private_event() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:11 [DEBUG] switch_ivr.c:455 switch_ivr_parse_event()
>> OpenZAP/1:1/21658519 Command Execute read(0 1 customer/hallo.wav
>> interrupt_digit 0 )
>> 2009-01-08 17:58:11 [DEBUG] switch_ivr_play_say.c:932
>> switch_ivr_play_file() Codec Activated L16 at 8000hz 1 channels 20ms
>> 2009-01-08 17:58:11 [DEBUG] switch_core_io.c:652
>> switch_core_session_write_frame() OpenZAP/1:1/21658519 receive
>> message
>> [TRANSCODING_NECESSARY]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 13
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 45 08 02 85 90 1e 02 82 88]
>>
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[45] Size:[115] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:455 zap_isdn_931_34()
>> Changing
>> state on 1:1 from UP to TERMINATING
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [TERMINATING]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:1121 state_advance()
>> Terminating: Direction Inbound
>> 2009-01-08 17:58:14 [DEBUG] mod_openzap.c:1418
>> on_clear_channel_signal()
>> got clear channel sig [STOP]
>> 2009-01-08 17:58:14 [NOTICE] mod_openzap.c:1437
>> on_clear_channel_signal() Hangup OpenZAP/1:1/21658519 [CS_EXECUTE]
>> [NORMAL_CLEARING]
>> 2009-01-08 17:58:14 [DEBUG] switch_channel.c:1513
>> switch_channel_perform_hangup() Send signal OpenZAP/1:1/21658519
>> [KILL]
>> 2009-01-08 17:58:14 [DEBUG] switch_core_session.c:807
>> switch_core_session_signal_state_change() Send signal
>> OpenZAP/1:1/21658519 [BREAK]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 11 4d]
>>
>> 2009-01-08 17:58:14 [DEBUG] mod_event_socket.c:1922 listener_run()
>> Session complete, waiting for children
>> 2009-01-08 17:58:14 [DEBUG] mod_event_socket.c:1946 listener_run()
>> Connection Closed
>> 2009-01-08 17:58:14 [DEBUG] switch_ivr_play_say.c:1222
>> switch_ivr_play_file() done playing file
>> 2009-01-08 17:58:14 [DEBUG] switch_core_state_machine.c:454
>> switch_core_session_run() (OpenZAP/1:1/21658519) State EXECUTE
>> going to
>> sleep
>> 2009-01-08 17:58:14 [DEBUG] switch_core_state_machine.c:379
>> switch_core_session_run() (OpenZAP/1:1/21658519) Running State Change
>> CS_HANGUP
>> 2009-01-08 17:58:14 [DEBUG] switch_core_state_machine.c:410
>> switch_core_session_run() (OpenZAP/1:1/21658519) State HANGUP
>> 2009-01-08 17:58:14 [DEBUG] mod_openzap.c:472 channel_on_hangup()
>> OpenZAP/1:1/21658519 CHANNEL HANGUP
>> 2009-01-08 17:58:14 [DEBUG] switch_core_state_machine.c:46
>> switch_core_standard_on_hangup() OpenZAP/1:1/21658519 Standard
>> HANGUP,
>> cause: NORMAL_CLEARING
>> 2009-01-08 17:58:14 [DEBUG] switch_core_state_machine.c:410
>> switch_core_session_run() (OpenZAP/1:1/21658519) State HANGUP going
>> to sleep
>> 2009-01-08 17:58:14 [DEBUG] switch_core_session.c:939
>> switch_core_session_thread() Session 46 (OpenZAP/1:1/21658519)
>> Locked,
>> Waiting on external entities
>> 2009-01-08 17:58:14 [NOTICE] switch_core_session.c:957
>> switch_core_session_thread() Session 46 (OpenZAP/1:1/21658519) Ended
>> 2009-01-08 17:58:14 [NOTICE] switch_core_session.c:959
>> switch_core_session_thread() Close Channel OpenZAP/1:1/21658519
>> [CS_HANGUP]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 11 5a]
>>
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[5a] Size:[103] CRV: 17 (0x11, CTX: Originator)
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34() zchan
>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:418 zap_isdn_931_34()
>> Changing
>> state on 1:1 from TERMINATING to DOWN
>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>> STATE
>> [DOWN]
>> 2009-01-08 17:58:14 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ
>> 40
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 46 05 04 03 80 90 a3 18 03 a1 83 81 6c 0c 21 81 36 39 33
>> 34 34
>> 30 39 32 30 30 70 09 c1 32 31 36 35 38 35 31 39]
>>
>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[05] Size:[179] CRV: 70 (0x46, CTX: Originator)
>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>> 2009-01-08 17:58:32 [WARNING] ozmod_isdn.c:572 zap_isdn_931_34()
>> Channel
>> 2:1 ~ 2:32 is already in use waiting for it to become available.
>> 2009-01-08 17:58:33 [ERR] ozmod_isdn.c:586 zap_isdn_931_34()
>> Channel 2:1
>> ~ 2:32 is already in use.
>> 2009-01-08 17:58:33 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 9
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 80 46 45 08 02 81 e5]
>>
>> 2009-01-08 17:58:33 [CRIT] ozmod_isdn.c:644 zap_isdn_931_34()
>> Failed to
>> open channel for new setup message
>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 46 4d]
>>
>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[4d] Size:[103] CRV: 70 (0x46, CTX: Originator)
>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>> 2009-01-08 17:58:34 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>> Received
>> Release with no matching channel 0
>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23() 931
>> parse
>> error [-3012] [Q931E_INVALID_CRV]
>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23() READ 5
>> ---
>> ---
>> ---
>> ---
>> --------------------------------------------------------------------
>> [08 02 00 46 4d]
>>
>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34() Yay
>> I got
>> an event! Type:[4d] Size:[103] CRV: 70 (0x46, CTX: Originator)
>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>> zchan 0
>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>> 2009-01-08 17:58:38 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>> Received
>> Release with no matching channel 0
>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23() 931
>> parse
>> error [-3012] [Q931E_INVALID_CRV]
>>
>> To see which channels he actually used in former times I grepped for
>> "channel done" in the log an got the following: Channel 2:1 ~ 2:32
>> should not be blocked as currently there are no more than 2
>> concurrent
>> calls while testing (1 incoming and 1 outgoing, we try to spread
>> outgoing over span1 and span2)
>>
>> 2009-01-08 14:16:20 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:17:38 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:19:26 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:22:11 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:24:47 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:27:50 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:32:40 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:39:47 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:24
>> 2009-01-08 14:39:47 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:40:48 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:44:20 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:46:33 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 14:50:42 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:07:13 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:12:36 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:16:08 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:18:31 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:29
>> 2009-01-08 15:18:33 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:19:21 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:24:20 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:26:08 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:27:10 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:28:07 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:33:54 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:1
>> 2009-01-08 15:35:05 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:39:55 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:48:27 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:51:55 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 15:58:53 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 16:05:41 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 16:09:15 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 16:18:21 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 16:18:57 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 16:19:17 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:24:07 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:8
>> 2009-01-08 17:24:15 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:29:13 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:31:49 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:32:28 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:35:35 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:38:09 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:10
>> 2009-01-08 17:38:50 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:39:44 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:39:58 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:2
>> 2009-01-08 17:40:02 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:40:10 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:40:18 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:40:32 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:40:43 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:40:55 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:41:07 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:42:53 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 2:10
>> 2009-01-08 17:42:53 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:43:14 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:44:47 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:56:05 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:56:48 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:57:29 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>> 2009-01-08 17:58:14 [DEBUG] zap_io.c:1125 zap_channel_done() channel
>> done 1:1
>>
>>
>> Michael Collins schrieb:
>>
>>> Can you pastebin a complete call history where the first call works,
>>> gets hung up and then the second call comes in? I would like to see
>>> the entire d-chan trace.
>>> -MC
>>>
>>> On Thu, Jan 8, 2009 at 9:15 AM, Peter P GMX
>>> <Prometheus001 at gmx.net> wrote:
>>>
>>>
>>>> We have a strange Issue on Openzap with a Digium PRI card (Digium
>>>> TE220
>>>> inkl. VPMOCT064 Octasic DSP-based echo cancellation module)
>>>>
>>>> Every second incoming call is successfoll, every second incoming
>>>> one
>>>> fails. For me it seems as if FS tries to use a channel which may be
>>>> still occupied?
>>>>
>>>> Anybody has an idea?
>>>>
>>>> Last hangup from successful!! call:
>>>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34()
>>>> Yay I got
>>>> an event! Type:[5a] Size:[103] CRV: 17 (0x11, CTX: Originator)
>>>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>>>> zchan
>>>> a001fb20 (1:1) source isdn_data->channels_remote_crv[0x11]
>>>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:418 zap_isdn_931_34()
>>>> Changing
>>>> state on 1:1 from TERMINATING to DOWN
>>>> 2009-01-08 17:58:14 [DEBUG] ozmod_isdn.c:813 state_advance() 1:1
>>>> STATE
>>>> [DOWN]
>>>> 2009-01-08 17:58:14 [DEBUG] zap_io.c:1125 zap_channel_done()
>>>> channel
>>>> done 1:1
>>>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23()
>>>> READ 40
>>>>
>>>>
>>>> 2nd Incoming Channel fails
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> -----------------------------------------------------------------
>>>> [08 02 00 46 05 04 03 80 90 a3 18 03 a1 83 81 6c 0c 21 81 36 39
>>>> 33 34 34
>>>> 30 39 32 30 30 70 09 c1 32 31 36 35 38 35 31 39]
>>>>
>>>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34()
>>>> Yay I got
>>>> an event! Type:[05] Size:[179] CRV: 70 (0x46, CTX: Originator)
>>>> 2009-01-08 17:58:32 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>>>> zchan 0
>>>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>>>> 2009-01-08 17:58:32 [WARNING] ozmod_isdn.c:572 zap_isdn_931_34()
>>>> Channel
>>>> 2:1 ~ 2:32 is already in use waiting for it to become available.
>>>> 2009-01-08 17:58:33 [ERR] ozmod_isdn.c:586 zap_isdn_931_34()
>>>> Channel 2:1
>>>> ~ 2:32 is already in use.
>>>> 2009-01-08 17:58:33 [DEBUG] ozmod_isdn.c:1529 q931_rx_32() WRITE 9
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> -----------------------------------------------------------------
>>>> [08 02 80 46 45 08 02 81 e5]
>>>>
>>>> 2009-01-08 17:58:33 [CRIT] ozmod_isdn.c:644 zap_isdn_931_34()
>>>> Failed to
>>>> open channel for new setup message
>>>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23()
>>>> READ 5
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> -----------------------------------------------------------------
>>>> [08 02 00 46 4d]
>>>>
>>>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34()
>>>> Yay I got
>>>> an event! Type:[4d] Size:[103] CRV: 70 (0x46, CTX: Originator)
>>>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>>>> zchan 0
>>>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>>>> 2009-01-08 17:58:34 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>>>> Received
>>>> Release with no matching channel 0
>>>> 2009-01-08 17:58:34 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23()
>>>> 931 parse
>>>> error [-3012] [Q931E_INVALID_CRV]
>>>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:777 zap_isdn_921_23()
>>>> READ 5
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> ---
>>>> -----------------------------------------------------------------
>>>> [08 02 00 46 4d]
>>>>
>>>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:320 zap_isdn_931_34()
>>>> Yay I got
>>>> an event! Type:[4d] Size:[103] CRV: 70 (0x46, CTX: Originator)
>>>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:352 zap_isdn_931_34()
>>>> zchan 0
>>>> (-1:-1) source isdn_data->channels_remote_crv[0x46]
>>>> 2009-01-08 17:58:38 [CRIT] ozmod_isdn.c:446 zap_isdn_931_34()
>>>> Received
>>>> Release with no matching channel 0
>>>> 2009-01-08 17:58:38 [DEBUG] ozmod_isdn.c:781 zap_isdn_921_23()
>>>> 931 parse
>>>> error [-3012] [Q931E_INVALID_CRV]
>>>>
>>>>
>>>> Best regards Peter
>>>>
>>>> _______________________________________________
>>>> Freeswitch-users mailing list
>>>> Freeswitch-users at lists.freeswitch.org
>>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>>> http://www.freeswitch.org
>>>>
>>>>
>>>>
>>> _______________________________________________
>>> Freeswitch-users mailing list
>>> Freeswitch-users at lists.freeswitch.org
>>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>>> http://www.freeswitch.org
>>>
>>>
>>>
>>
>> _______________________________________________
>> Freeswitch-users mailing list
>> Freeswitch-users at lists.freeswitch.org
>> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
>> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
>> http://www.freeswitch.org
>>
>>
>
> _______________________________________________
> Freeswitch-users mailing list
> Freeswitch-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
More information about the FreeSWITCH-users
mailing list