[Freeswitch-users] Problem with mod_openzap.c and SS7boost

Tue Oct 28 09:03:09 PDT 2008

-----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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at sip1.ewetel.net) State HANGUP
2008-10-28 16:52:48 [DEBUG] mod_sofia.c:276 sofia_on_hangup() Channel
sofia/softswitch_side/031152112850 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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-----