:) Sent from my iPhone
On Jan 9, 2009, at 7:38 AM, Peter P GMX <[email protected]> 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 l...@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 >>> <[email protected]> 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 >>>> [email protected] >>>> 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 >>> [email protected] >>> 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 >> [email protected] >> 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 > [email protected] > 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 [email protected] http://lists.freeswitch.org/mailman/listinfo/freeswitch-users UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users http://www.freeswitch.org
