-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Hi Anthony, I'm not familar with mod_openzap code nor with ss7boost stuff. I'm not sure if the hack introduce some bad side effects but I know it seems to solve this special problem. I can reproduce it any time. Problem was, that when I make a call into pstn and cancel it very shortly ( 0.5 .. 1 second after putting the call to openzap) after that the pstn side remains ringing until timout. It seems to me that the case is not considered when pstn side is initiating and zap state is still ZAP_CHANNEL_STATE_DOWN and call is canceled. When the problem occures the tech_pvt->zchan->state is ZAP_CHANNEL_STATE_DOWN (0) Here is FS debug log when the problem occurs: Important part is marked with some '!' 2008-10-28 16:52:47 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/softswitch_side/031152112850@sip1.ewetel.net Execute bridge(OpenZAP/1/a/44180002850) 2008-10-28 16:52:47 [DEBUG] ozmod_ss7_boost.c:225 ss7_boost_channel_request() TX EVENT: CALL_START:(80) [w1g1] CSid=5 Seq=6 Cn=[hk] Cd=[44180002850] Ci=[31152112850] 2008-10-28 16:52:47 [DEBUG] sofia.c:2269 sofia_handle_sip_i_state() Channel sofia/softswitch_side/031152112850@sip1.ewetel.net entering state [terminated] 2008-10-28 16:52:47 [NOTICE] sofia.c:2765 sofia_handle_sip_i_state() Hangup sofia/softswitch_side/031152112850@sip1.ewetel.net [CS_EXECUTE] [ORIGINATOR_CANCEL] 2008-10-28 16:52:47 [DEBUG] switch_channel.c:1449 switch_channel_perform_hangup() Send signal sofia/softswitch_side/031152112850@sip1.ewetel.net [KILL] 2008-10-28 16:52:47 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/softswitch_side/031152112850@sip1.ewetel.net [BREAK] 2008-10-28 16:52:48 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_START_ACK:(81) [w1g30] Rc=0 CSid=5 Seq=8 2008-10-28 16:52:48 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:52:48 [DEBUG] ozmod_ss7_boost.c:296 handle_call_start_ack() Assign chan 1:29 (1:30) CSid=5 2008-10-28 16:52:48 [DEBUG] mod_openzap.c:340 tech_init() Set codec PCMA 20ms 2008-10-28 16:52:48 [DEBUG] mod_openzap.c:1020 channel_outgoing_channel() Connect outbound channel OpenZAP/1:29/44180002850 2008-10-28 16:52:48 [NOTICE] switch_channel.c:553 switch_channel_set_name() New Channel OpenZAP/1:29/44180002850 [c1e6d98e-6654-4d6c-8e1b-41a4b3a52d39] 2008-10-28 16:52:48 [DEBUG] mod_openzap.c:1029 channel_outgoing_channel() (OpenZAP/1:29/44180002850) State Change CS_NEW -> CS_INIT 2008-10-28 16:52:48 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal OpenZAP/1:29/44180002850 [BREAK] 2008-10-28 16:52:48 [DEBUG] switch_ivr_originate.c:1598 switch_ivr_originate() Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2008-10-28 16:52:48 [NOTICE] switch_ivr_originate.c:1637 switch_ivr_originate() Hangup OpenZAP/1:29/44180002850 [CS_INIT] [ORIGINATOR_CANCEL] 2008-10-28 16:52:48 [DEBUG] switch_channel.c:1449 switch_channel_perform_hangup() Send signal OpenZAP/1:29/44180002850 [KILL] 2008-10-28 16:52:48 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal OpenZAP/1:29/44180002850 [BREAK] 2008-10-28 16:52:48 [INFO] mod_dptools.c:1843 audio_bridge_function() Originate Failed. Cause: ORIGINATOR_CANCEL 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State EXECUTE going to sleep 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) Running State Change CS_HANGUP 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State HANGUP 2008-10-28 16:52:48 [DEBUG] mod_sofia.c:276 sofia_on_hangup() Channel sofia/softswitch_side/031152112850@sip1.ewetel.net hanging up, cause: ORIGINATOR_CANCEL 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/softswitch_side/031152112850@sip1.ewetel.net Standard HANGUP, cause: ORIGINATOR_CANCEL 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State HANGUP going to sleep 2008-10-28 16:52:48 [DEBUG] switch_core_session.c:860 switch_core_session_thread() Session 8 (sofia/softswitch_side/031152112850@sip1.ewetel.net) Locked, Waiting on external entities 2008-10-28 16:52:48 [NOTICE] switch_core_session.c:878 switch_core_session_thread() Session 8 (sofia/softswitch_side/031152112850@sip1.ewetel.net) Ended 2008-10-28 16:52:48 [NOTICE] switch_core_session.c:880 switch_core_session_thread() Close Channel sofia/softswitch_side/031152112850@sip1.ewetel.net [CS_HANGUP] 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() (OpenZAP/1:29/44180002850) Running State Change CS_HANGUP 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (OpenZAP/1:29/44180002850) State HANGUP !!!!!!!!!!!!!!!!!!!!!!!!! 2008-10-28 16:52:48 [INFO] mod_openzap.c:446 channel_on_hangup() ZAP-STATE is '0' 2008-10-28 16:52:48 [DEBUG] mod_openzap.c:474 channel_on_hangup() OpenZAP/1:29/44180002850 CHANNEL HANGUP !!!!!!!!!!!!!!!!!!!!!!!!! 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() OpenZAP/1:29/44180002850 Standard HANGUP, cause: ORIGINATOR_CANCEL 2008-10-28 16:52:48 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (OpenZAP/1:29/44180002850) State HANGUP going to sleep 2008-10-28 16:52:48 [DEBUG] switch_core_session.c:860 switch_core_session_thread() Session 9 (OpenZAP/1:29/44180002850) Locked, Waiting on external entities 2008-10-28 16:52:48 [NOTICE] switch_core_session.c:878 switch_core_session_thread() Session 9 (OpenZAP/1:29/44180002850) Ended 2008-10-28 16:52:48 [NOTICE] switch_core_session.c:880 switch_core_session_thread() Close Channel OpenZAP/1:29/44180002850 [CS_HANGUP] 2008-10-28 16:52:48 [DEBUG] switch_core_codec.c:76 switch_core_session_set_read_codec() resetting to uninitilized codec, setting to NULL 2008-10-28 16:52:50 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_ANSWERED:(84) [w1g30] Rc=0 CSid=5 Seq=9 2008-10-28 16:52:50 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_STOPPED:(85) [w1g31] Rc=16 CSid=4 Seq=10 2008-10-28 16:53:07 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:408 handle_call_stop() Changing state on 1:30 from DOWN to TERMINATING 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [TERMINATING] 2008-10-28 16:53:07 [DEBUG] mod_openzap.c:1437 on_clear_channel_signal() got clear channel sig [STOP] 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:782 state_advance() Changing state on 1:30 from TERMINATING to HANGUP_COMPLETE 2008-10-28 16:53:07 [DEBUG] ss7_boost_client.c:216 ss7bc_exec_command() TX EVENT (N): CALL_STOPPED_ACK:(86) [w1g31] Rc=0 CSid=0 Seq=7 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [HANGUP_COMPLETE] 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:736 state_advance() Changing state on 1:30 from HANGUP_COMPLETE to DOWN 2008-10-28 16:53:07 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [DOWN] 2008-10-28 16:53:07 [DEBUG] zap_io.c:1123 zap_channel_done() channel done 1:30 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_STOPPED:(85) [w1g30] Rc=16 CSid=5 Seq=11 2008-10-28 16:53:14 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:408 handle_call_stop() Changing state on 1:29 from DOWN to TERMINATING 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:29 STATE [TERMINATING] 2008-10-28 16:53:14 [DEBUG] mod_openzap.c:1437 on_clear_channel_signal() got clear channel sig [STOP] 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:782 state_advance() Changing state on 1:29 from TERMINATING to HANGUP_COMPLETE 2008-10-28 16:53:14 [DEBUG] ss7_boost_client.c:216 ss7bc_exec_command() TX EVENT (N): CALL_STOPPED_ACK:(86) [w1g30] Rc=0 CSid=0 Seq=8 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:29 STATE [HANGUP_COMPLETE] 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:736 state_advance() Changing state on 1:29 from HANGUP_COMPLETE to DOWN 2008-10-28 16:53:14 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:29 STATE [DOWN] 2008-10-28 16:53:14 [DEBUG] zap_io.c:1123 zap_channel_done() channel done 1:29 And here is the log, when my little hack is applied: Important part is marked with some '!' 2008-10-28 16:55:38 [DEBUG] switch_core_state_machine.c:144 switch_core_standard_on_execute() sofia/softswitch_side/031152112850@sip1.ewetel.net Execute bridge(OpenZAP/1/a/44180002850) 2008-10-28 16:55:38 [DEBUG] ozmod_ss7_boost.c:225 ss7_boost_channel_request() TX EVENT: CALL_START:(80) [w1g1] CSid=1 Seq=0 Cn=[hk] Cd=[44180002850] Ci=[31152112850] 2008-10-28 16:55:39 [DEBUG] sofia.c:2269 sofia_handle_sip_i_state() Channel sofia/softswitch_side/031152112850@sip1.ewetel.net entering state [terminated] 2008-10-28 16:55:39 [NOTICE] sofia.c:2765 sofia_handle_sip_i_state() Hangup sofia/softswitch_side/031152112850@sip1.ewetel.net [CS_EXECUTE] [ORIGINATOR_CANCEL] 2008-10-28 16:55:39 [DEBUG] switch_channel.c:1449 switch_channel_perform_hangup() Send signal sofia/softswitch_side/031152112850@sip1.ewetel.net [KILL] 2008-10-28 16:55:39 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal sofia/softswitch_side/031152112850@sip1.ewetel.net [BREAK] 2008-10-28 16:55:39 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_START_ACK:(81) [w1g31] Rc=0 CSid=1 Seq=1 2008-10-28 16:55:39 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:55:39 [DEBUG] ozmod_ss7_boost.c:296 handle_call_start_ack() Assign chan 1:30 (1:31) CSid=1 2008-10-28 16:55:39 [DEBUG] mod_openzap.c:340 tech_init() Set codec PCMA 20ms 2008-10-28 16:55:39 [DEBUG] mod_openzap.c:1020 channel_outgoing_channel() Connect outbound channel OpenZAP/1:30/44180002850 2008-10-28 16:55:39 [NOTICE] switch_channel.c:553 switch_channel_set_name() New Channel OpenZAP/1:30/44180002850 [cf5117e3-bd44-40b6-8dec-2bc211f51e97] 2008-10-28 16:55:39 [DEBUG] mod_openzap.c:1029 channel_outgoing_channel() (OpenZAP/1:30/44180002850) State Change CS_NEW -> CS_INIT 2008-10-28 16:55:39 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal OpenZAP/1:30/44180002850 [BREAK] 2008-10-28 16:55:39 [DEBUG] switch_ivr_originate.c:1598 switch_ivr_originate() Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2008-10-28 16:55:39 [NOTICE] switch_ivr_originate.c:1637 switch_ivr_originate() Hangup OpenZAP/1:30/44180002850 [CS_INIT] [ORIGINATOR_CANCEL] 2008-10-28 16:55:39 [DEBUG] switch_channel.c:1449 switch_channel_perform_hangup() Send signal OpenZAP/1:30/44180002850 [KILL] 2008-10-28 16:55:39 [DEBUG] switch_core_session.c:727 switch_core_session_signal_state_change() Send signal OpenZAP/1:30/44180002850 [BREAK] 2008-10-28 16:55:39 [INFO] mod_dptools.c:1843 audio_bridge_function() Originate Failed. Cause: ORIGINATOR_CANCEL 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State EXECUTE going to sleep 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) Running State Change CS_HANGUP 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:367 switch_core_session_run() (OpenZAP/1:30/44180002850) Running State Change CS_HANGUP 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State HANGUP 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (OpenZAP/1:30/44180002850) State HANGUP 2008-10-28 16:55:39 [DEBUG] mod_sofia.c:276 sofia_on_hangup() Channel sofia/softswitch_side/031152112850@sip1.ewetel.net hanging up, cause: ORIGINATOR_CANCEL !!!!!!!!!!!!!!!!!!!!!!!!!! 2008-10-28 16:55:39 [INFO] mod_openzap.c:446 channel_on_hangup() ZAP-STATE is '0' 2008-10-28 16:55:39 [DEBUG] mod_openzap.c:453 channel_on_hangup() Changing state on 1:30 from DOWN to HANGUP 2008-10-28 16:55:39 [DEBUG] mod_openzap.c:474 channel_on_hangup() OpenZAP/1:30/44180002850 CHANNEL HANGUP !!!!!!!!!!!!!!!!!!!!!!!!!!! 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() OpenZAP/1:30/44180002850 Standard HANGUP, cause: ORIGINATOR_CANCEL 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/softswitch_side/031152112850@sip1.ewetel.net Standard HANGUP, cause: ORIGINATOR_CANCEL 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (OpenZAP/1:30/44180002850) State HANGUP going to sleep 2008-10-28 16:55:39 [DEBUG] switch_core_state_machine.c:395 switch_core_session_run() (sofia/softswitch_side/031152112850@sip1.ewetel.net) State HANGUP going to sleep 2008-10-28 16:55:39 [DEBUG] switch_core_session.c:860 switch_core_session_thread() Session 2 (OpenZAP/1:30/44180002850) Locked, Waiting on external entities 2008-10-28 16:55:39 [DEBUG] switch_core_session.c:860 switch_core_session_thread() Session 1 (sofia/softswitch_side/031152112850@sip1.ewetel.net) Locked, Waiting on external entities 2008-10-28 16:55:39 [NOTICE] switch_core_session.c:878 switch_core_session_thread() Session 2 (OpenZAP/1:30/44180002850) Ended 2008-10-28 16:55:39 [NOTICE] switch_core_session.c:878 switch_core_session_thread() Session 1 (sofia/softswitch_side/031152112850@sip1.ewetel.net) Ended 2008-10-28 16:55:39 [NOTICE] switch_core_session.c:880 switch_core_session_thread() Close Channel OpenZAP/1:30/44180002850 [CS_HANGUP] 2008-10-28 16:55:39 [NOTICE] switch_core_session.c:880 switch_core_session_thread() Close Channel sofia/softswitch_side/031152112850@sip1.ewetel.net [CS_HANGUP] 2008-10-28 16:55:39 [DEBUG] switch_core_codec.c:76 switch_core_session_set_read_codec() resetting to uninitilized codec, setting to NULL 2008-10-28 16:55:39 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [HANGUP] 2008-10-28 16:55:39 [DEBUG] ss7_boost_client.c:216 ss7bc_exec_command() TX EVENT (N): CALL_START_NACK:(82) [w1g31] Rc=16 CSid=0 Seq=1 2008-10-28 16:55:40 [DEBUG] ozmod_ss7_boost.c:932 zap_ss7_boost_run() RX EVENT (N): CALL_START_NACK_ACK:(83) [w1g31] Rc=0 CSid=1 Seq=2 2008-10-28 16:55:40 [DEBUG] ss7_boost_client.c:300 __ss7bc_connection_read() Rx sync ok 2008-10-28 16:55:40 [DEBUG] ozmod_ss7_boost.c:333 handle_call_done() Changing state on 1:30 from HANGUP to HANGUP_COMPLETE 2008-10-28 16:55:40 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [HANGUP_COMPLETE] 2008-10-28 16:55:40 [DEBUG] ozmod_ss7_boost.c:736 state_advance() Changing state on 1:30 from HANGUP_COMPLETE to DOWN 2008-10-28 16:55:40 [DEBUG] ozmod_ss7_boost.c:644 state_advance() 1:30 STATE [DOWN] 2008-10-28 16:55:40 [DEBUG] zap_io.c:1123 zap_channel_done() channel done 1:30 regards Helmut -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.9 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iEYEARECAAYFAkkHN70ACgkQ4tZeNddg3dw86gCgkFql8szq3u8/aOIcr9FNz4Gz bBsAn0n+unK6p48XZd3y+ESEf96WNm+8 =7ZI6 -----END PGP SIGNATURE-----