[Freeswitch-dev] OZ: possible issue with false positives in Q931IsIEPresent macro

Sat Jun 21 15:16:29 EDT 2008

FYI,

After much pain I am able to say that I can consistently reproduce this
scenario: 

In zap_isdn.c, function zap_isdn_931_34, I can always get the
Q931IsIEPresent macro to see a cause ie, whether one is present or not.

I've added this snippet toward the beginning of the function:

      if (Q931IsIEPresent(gen->Cause)) {

            zap_log(ZAP_LOG_DEBUG, "Cause ie present
[%x]\n",gen->Cause);

      }

Raw output is as follows; note that all inbound q931 message say that a
cause ie is present, even when one isn't:

freeswitch at freeswitch2.fcnetwork.com> originate
{origination_caller_id_number=80

05409011,dname='Busy',dnum='5898832',dialednum='5597332791',agentinfo='5
898832.2

791',bcast='Mikey_test'}openzap/1/a/5597332791 825597332791

2008-06-21 12:12:43 [DEBUG] zap_isdn.c:56 isdn_outgoing_call() Changing
state on

 1:1 from DOWN to DIALING

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:365
switch_core_session_

run() OpenZAP/1:1/5597332791 Running State Change CS_INIT

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:415
switch_core_session_

run() (OpenZAP/1:1/5597332791) State INIT

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:415
switch_core_session_

run() (OpenZAP/1:1/5597332791) State INIT going to sleep

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:365
switch_core_session_

run() OpenZAP/1:1/5597332791 Running State Change CS_ROUTING

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:420
switch_core_session_

run() (OpenZAP/1:1/5597332791) State ROUTING

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:420
switch_core_session_

run() (OpenZAP/1:1/5597332791) State ROUTING going to sleep

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:365
switch_core_session_

run() OpenZAP/1:1/5597332791 Running State Change CS_CONSUME_MEDIA

2008-06-21 12:12:43 [DEBUG] switch_core_state_machine.c:442
switch_core_session_

run() (OpenZAP/1:1/5597332791) State CONSUME_MEDIA

2008-06-21 12:12:44 [ERR] zap_isdn.c:589 state_advance() 1:1 STATE
[DIALING]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:987 q931_rx_32() WRITE 58

------------------------------------------------------------------------
--------

[00 01 00 00 08 02 00 02 05 04 03 80 90 a2 18 03 a1 83 81 28 0a 46 72 65
65 53 5

7 49 54 43 48 6c 0c 21 80 38 30 30 35 34 30 39 30 31 31 70 0b a1 35 35
39 37 33

33 32 37 39 31]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:556 zap_isdn_921_23() READ 13

------------------------------------------------------------------------
--------

[08 02 80 02 7d 08 03 81 ab 28 14 01 01]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:284 zap_isdn_931_34() Yay I got
an event!

 Type:[7d] Size:[114]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:287 zap_isdn_931_34() Cause ie
present [8

000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:556 zap_isdn_921_23() READ 10

------------------------------------------------------------------------
--------

[08 02 80 02 02 18 03 a9 83 81]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:284 zap_isdn_931_34() Yay I got
an event!

 Type:[02] Size:[137]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:287 zap_isdn_931_34() Cause ie
present [8

000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:556 zap_isdn_921_23() READ 9

------------------------------------------------------------------------
--------

[08 02 80 02 03 1e 02 81 88]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:284 zap_isdn_931_34() Yay I got
an event!

 Type:[03] Size:[108]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:287 zap_isdn_931_34() Cause ie
present [8

000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:428 zap_isdn_931_34() Cause info
[8000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:434 zap_isdn_931_34() PROGRESS
message wi

th cause value of '0'

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:556 zap_isdn_921_23() READ 13

------------------------------------------------------------------------
--------

[08 02 80 02 03 08 02 81 91 1e 02 81 88]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:284 zap_isdn_931_34() Yay I got
an event!

 Type:[03] Size:[115]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:287 zap_isdn_931_34() Cause ie
present [8

000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:428 zap_isdn_931_34() Cause info
[8000]

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:434 zap_isdn_931_34() PROGRESS
message wi

th cause value of '17'

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:436 zap_isdn_931_34() Changing
state on 1

:1 from DIALING to TERMINATING

2008-06-21 12:12:44 [ERR] zap_isdn.c:589 state_advance() 1:1 STATE
[TERMINATING]

API CALL
[originate({origination_caller_id_number=8005409011,dname='Busy',dnum='

5898832',dialednum='5597332791',agentinfo='5898832.2791',bcast='Mikey_te
st'}open

zap/1/a/5597332791 825597332791)] output:

-ERR USER_BUSY

2008-06-21 12:12:44 [DEBUG] zap_isdn.c:987 q931_rx_32() WRITE 21

------------------------------------------------------------------------
--------

[00 01 02 08 08 02 00 02 4d 28 0a 46 72 65 65 53 57 49 54 43 48]

2008-06-21 12:12:44 [DEBUG] switch_core_state_machine.c:442
switch_core_session_

run() (OpenZAP/1:1/5597332791) State CONSUME_MEDIA going to sleep

2008-06-21 12:12:44 [DEBUG] switch_core_state_machine.c:365
switch_core_session_

run() OpenZAP/1:1/5597332791 Running State Change CS_HANGUP

2008-06-21 12:12:44 [DEBUG] switch_core_state_machine.c:393
switch_core_session_

run() (OpenZAP/1:1/5597332791) State HANGUP

freeswitch at freeswitch2.fcnetwork.com> 2008-06-21 12:12:44 [DEBUG]
switch_core_st

ate_machine.c:46 switch_core_standard_on_hangup() Standard HANGUP
OpenZAP/1:1/55

97332791, cause: USER_BUSY

2008-06-21 12:12:44 [DEBUG] switch_core_state_machine.c:393
switch_core_session_

run() (OpenZAP/1:1/5597332791) State HANGUP going to sleep

2008-06-21 12:12:45 [DEBUG] zap_isdn.c:556 zap_isdn_921_23() READ 10

------------------------------------------------------------------------
--------

[08 02 80 02 5a 08 03 81 e0 08]

2008-06-21 12:12:45 [DEBUG] zap_isdn.c:284 zap_isdn_931_34() Yay I got
an event!

 Type:[5a] Size:[110]

2008-06-21 12:12:45 [DEBUG] zap_isdn.c:287 zap_isdn_931_34() Cause ie
present [8

000]

2008-06-21 12:12:45 [DEBUG] zap_isdn.c:386 zap_isdn_931_34() Changing
state on 1

:1 from TERMINATING to HANGUP_COMPLETE

2008-06-21 12:12:45 [ERR] zap_isdn.c:589 state_advance() 1:1 STATE
[HANGUP_COMPL

ETE]

2008-06-21 12:12:45 [DEBUG] zap_isdn.c:761 state_advance() Changing
state on 1:1

 from HANGUP_COMPLETE to DOWN

2008-06-21 12:12:45 [ERR] zap_isdn.c:589 state_advance() 1:1 STATE
[DOWN]

2008-06-21 12:12:45 [DEBUG] zap_io.c:1071 zap_channel_done() channel
done 1:1

Anyway, I thought I'd share.  If you think this is jira-worthy I'll post
a new issue, otherwise if you know why the gen->Cause is always showing
up as present I'd be happy to fix and test.  For the record, the test is
a bitwise AND, where the "cause" value is ANDed against 0x8000.  Since
the gen->Cause value seems always to be 0x8000, whether it is present or
not, it always comes up as true.

Thanks for your thoughts and suggestions.

-MC

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-dev/attachments/20080621/96633be4/attachment-0001.html 