[Home]

Summary:ASTERISK-02004: Problem with Sip UNKN (d)
Reporter:erik123 (erik123)Labels:
Date Opened:2004-07-13 10:54:07Date Closed:2004-09-25 02:37:48
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) sipdeb.tgz
Description:Tones of not destroing channels

****** ADDITIONAL INFORMATION ******

192.168.0.206    3006        00fc32fb509  00102/00000   ULAW
192.168.0.103    3005        43b75f1a5da  00102/35154   UNKN  (d)
192.168.0.100    3002        3aa0741552c  00102/00000   ULAW
192.168.0.124    3003        3b4b9742093  00102/00000   ULAW
192.168.0.103    3005        0331fde9035  00102/19028   UNKN  (d)
192.168.0.203    3009        13d3b3f51da  00102/08982   UNKN  (d)
192.168.0.103    3005        64ec8737586  00102/48304   UNKN  (d)
192.168.0.208    3011        78a87ed6248  00102/63726   UNKN  (d)
192.168.0.44     3001        671bd952289  00102/09429   UNKN  (d)
192.168.0.111    3007        23770b7d692  00102/47264   UNKN  (d)
192.168.0.124    3003        46834faf07c  00102/27314   UNKN  (d)
192.168.0.203    3009        1a4f1c86183  00102/06534   UNKN  (d)
192.168.0.124    3003        7c389085314  00102/00247   UNKN  (d)
192.168.0.100    3002        6eb266a732d  00102/26262   UNKN  (d)
192.168.0.203    3009        3b988dd1566  00102/56505   UNKN  (d)
192.168.0.203    3009        587af2e7430  00102/16434   UNKN  (d)
192.168.0.208    3011        503b185b40a  00102/10376   UNKN  (d)
192.168.0.203    3009        4ffb231d230  00102/31731   UNKN  (d)
192.168.0.103    3005        5b64ad0457a  00102/02815   UNKN  (d)
192.168.0.103    3005        2ffe7c39374  00102/58074   UNKN  (d)
192.168.0.103    3005        69f8e52e3f2  00102/04459   UNKN  (d)
192.168.0.111    3007        11c24137370  00102/45040   UNKN  (d)
192.168.0.111    3007        2b5629300fb  00102/05345   UNKN  (d)
192.168.0.103    3005        6801d248188  00102/27472   UNKN  (d)
192.168.0.103    3005        5b914cbd4c4  00102/00735   UNKN  (d)
192.168.0.203    3009        25d563c0585  00102/10838   UNKN  (d)
192.168.0.103    3005        1190566c3a6  00102/03594   UNKN  (d)
192.168.0.103    3005        38cd74cb300  00102/31732   UNKN  (d)
192.168.0.44     3001        04cfd6d669d  00102/47714   UNKN  (d)
192.168.0.103    3005        518d24ab271  00102/08069   UNKN  (d)
192.168.0.44     3001        3e6b576d0d1  00102/05441   UNKN  (d)
192.168.0.103    3005        1bdd28e652d  00102/53384   UNKN  (d)
192.168.0.111    3007        63273436447  00102/55091   UNKN  (d)
192.168.0.203    3009        5360b6cb184  00102/26541   UNKN  (d)
192.168.0.103    3005        68d79b3918c  00102/55761   UNKN  (d)
192.168.0.103    3005        6c3c08e02c3  00102/24519   UNKN  (d)
192.168.0.103    3005        6fdb143301e  00102/32730   UNKN  (d)
192.168.0.103    3005        23fae5a54ba  00102/02126   UNKN  (d)
192.168.0.203    3009        53b45a240a0  00102/26869   UNKN  (d)
192.168.0.100    3002        6382619a183  00102/03123   UNKN  (d)
192.168.0.111    3007        2b92738e729  00102/49053   UNKN  (d)
192.168.0.206    3006        1c7ee9a051e  00102/32510   UNKN  (d)
192.168.0.103    3005        5fb786ec09f  00102/63295   UNKN  (d)
192.168.0.206    3006        42c7b90650c  00102/57915   UNKN  (d)
192.168.0.103    3005        33d0e5043e8  00102/12464   UNKN  (d)
192.168.0.103    3005        243045061e1  00102/37757   UNKN  (d)
192.168.0.103    3005        24f880e110b  00102/20748   UNKN  (d)
192.168.0.44     3001        367f8c1d2b4  00102/20025   UNKN  (d)
192.168.0.111    3007        104466fd1b2  00102/25398   UNKN  (d)
192.168.0.100    3002        32b9814808d  00102/58165   UNKN  (d)
192.168.0.203    3009        40e07b4b1a3  00102/39168   UNKN  (d)
192.168.0.103    3005        76bc737f488  00102/04232   UNKN  (d)
192.168.0.44     3001        6418ec6300a  00102/58372   UNKN  (d)
192.168.0.103    3005        5cd5a3b615e  00102/60472   UNKN  (d)
192.168.0.103    3005        3859af201f8  00102/16131   UNKN  (d)
192.168.0.103    3005        3c2a724437c  00102/57139   UNKN  (d)
192.168.0.203    3009        4212153e152  00102/13466   UNKN  (d)
192.168.0.203    3009        1f5a364176f  00102/20515   UNKN  (d)
192.168.0.103    3005        32255f70053  00102/28788   UNKN  (d)
192.168.0.44     3001        59e8a49034a  00102/23705   UNKN  (d)
192.168.0.103    3005        0de0c4ba4f1  00102/41192   UNKN  (d)
192.168.0.206    3006        156f0470220  00102/54697   UNKN  (d)
192.168.0.103    3005        06503e4c4fd  00102/52868   UNKN  (d)
192.168.0.206    3006        1543781d708  00102/29259   UNKN  (d)
192.168.0.103    3005        5922324d31c  00102/02569   UNKN  (d)
192.168.0.103    3005        4f4706e132e  00102/64374   UNKN  (d)
192.168.0.208    3011        39317b20708  00102/01677   UNKN  (d)
192.168.0.103    3005        692e7a6a081  00102/30460   UNKN  (d)
192.168.0.103    3005        3b21337c340  00102/44052   UNKN  (d)
192.168.0.103    3005        591119f91dc  00102/01832   UNKN  (d)
192.168.0.103    3005        72679abc568  00102/00630   UNKN  (d)
192.168.0.103    3005        7e3c8c31532  00102/52042   UNKN  (d)
192.168.0.103    3005        57e1f37272e  00102/07503   UNKN  (d)
192.168.0.100    3002        2422e6d457f  00102/30881   UNKN  (d)
192.168.0.103    3005        06c6043b1e0  00102/45538   UNKN  (d)
192.168.0.44     3001        2b31cc8c018  00102/13585   UNKN  (d)
192.168.0.103    3005        467b7d285d4  00102/04523   UNKN  (d)
192.168.0.103    3005        6f7ed20f104  00102/41634   UNKN  (d)
192.168.0.103    3005        7cc80e4f693  00102/39398   UNKN  (d)
192.168.0.103    3005        7f1aa9e7175  00102/11778   UNKN  (d)
192.168.0.103    3005        2c07f1d5724  00102/56073   UNKN  (d)
192.168.0.103    3005        5074049560b  00102/27185   UNKN  (d)
192.168.0.103    3005        15700519114  00102/59078   UNKN  (d)
192.168.0.206    3006        761f3c7734a  00102/08791   UNKN  (d)
192.168.0.103    3005        06da3ee634e  00102/14967   UNKN  (d)
192.168.0.103    3005        78a98d837b4  00102/11416   UNKN  (d)
192.168.0.100    3002        01b169dc1ff  00102/29995   UNKN  (d)
192.168.0.103    3005        02a85b980d2  00102/08051   UNKN  (d)
192.168.0.103    3005        413459eb592  00102/45713   UNKN  (d)
192.168.0.103    3005        19657d6e6eb  00102/55702   UNKN  (d)
192.168.0.203    3009        34ab0f57310  00102/41013   UNKN  (d)
192.168.0.203    3009        7fe953793d6  00102/25389   UNKN  (d)
192.168.0.103    3005        750ca324325  00102/07592   UNKN  (d)
192.168.0.100    3002        73ae02ba26e  00102/57240   UNKN  (d)
192.168.0.103    3005        267b35a6702  00102/28141   UNKN  (d)
192.168.0.103    3005        53f1aab0485  00102/62103   UNKN  (d)
192.168.0.203    3009        014f9ec00db  00102/08673   UNKN  (d)
192.168.0.100    3002        7f1d8126523  00102/40284   UNKN  (d)
192.168.0.206    3006        4cd9abd019d  00102/42931   UNKN  (d)
192.168.0.100    3002        41a6cfe30d5  00102/58260   UNKN  (d)
192.168.0.106    3004        04aabe650cf  00102/61279   UNKN  (d)
192.168.0.203    3009        5f318cfe1f1  00102/24756   UNKN  (d)
192.168.0.44     3001        0dc6f75e1c1  00102/13179   UNKN  (d)
192.168.0.203    3009        6232a02e38a  00102/51679   UNKN  (d)
192.168.0.124    3003        138a3d642ae  00102/61415   UNKN  (d)
192.168.0.111    3007        013e6d412c9  00102/15105   UNKN  (d)
192.168.0.111    3007        7ef61950041  00102/58232   UNKN  (d)
192.168.0.44     3001        44ad6e931a0  00102/43464   UNKN  (d)
192.168.0.106    3004        648c853e61b  00102/41272   UNKN  (d)
192.168.0.203    3009        4ca5419b056  00102/41131   UNKN  (d)
192.168.0.124    3003        698d222b356  00102/47483   UNKN  (d)
192.168.0.100    3002        1cbb970c0e1  00102/51221   UNKN  (d)
192.168.0.124    3003        52e8f6762e2  00102/23125   UNKN  (d)
192.168.0.124    3003        3118a2c91d7  00102/14229   UNKN  (d)
192.168.0.100    3002        2aecddfa600  00102/37876   UNKN  (d)
192.168.0.100    3002        2683b19771b  00102/32583   UNKN  (d)
192.168.0.206    3006        44fc43ef085  00102/40945   UNKN  (d)
192.168.0.124    3003        08c5f2861f4  00102/52712   UNKN  (d)
192.168.0.100    3002        7dc4fa8803e  00102/07728   UNKN  (d)
192.168.0.100    3002        2ba0167a07c  00102/35431   UNKN  (d)
192.168.0.124    3003        732ef9306e7  00102/30055   UNKN  (d)
192.168.0.100    3002        020600fc669  00102/31736   UNKN  (d)
192.168.0.100    3002        4584bcc87fe  00102/61547   UNKN  (d)
192.168.0.203    3009        01adf52531e  00102/28851   UNKN  (d)
192.168.0.44     3001        765a5af67a0  00102/19464   UNKN  (d)
192.168.0.206    3006        0864db69222  00102/32104   UNKN  (d)
192.168.0.206    3006        0c39e0b51cc  00102/10867   UNKN  (d)
192.168.0.206    3006        5ee64a7c0ac  00102/01836   UNKN  (d)
192.168.0.44     3001        43b6defb4de  00102/50450   UNKN  (d)
192.168.0.124    3003        42b2763f063  00102/64804   UNKN  (d)
192.168.0.124    3003        7c8a48593c1  00102/17631   UNKN  (d)
192.168.0.124    3003        76325b0570a  00102/65150   UNKN  (d)
192.168.0.44     3001        798a1a497d1  00102/28360   UNKN  (d)
192.168.0.203    3009        6a44c321768  00102/15484   UNKN  (d)
192.168.0.111    3007        7c98894a1a4  00102/25195   UNKN  (d)
192.168.0.203    3009        525aba5c3b1  00102/07254   UNKN  (d)
192.168.0.100    3002        4a392e9e589  00102/23429   UNKN  (d)
192.168.0.106    3004        72ee8f6137b  00102/10443   UNKN  (d)
192.168.0.124    3003        267773957fc  00102/01741   UNKN  (d)
192.168.0.203    3009        39cbfa8d6a0  00102/53934   UNKN  (d)
192.168.0.124    3003        066d2a7d457  00102/40865   UNKN  (d)
192.168.0.124    3003        745caa3a781  00102/50598   UNKN  (d)
192.168.0.103    3005        7ceeb7f86e1  00102/49836   UNKN  (d)
192.168.0.124    3003        446365db06b  00102/42045   UNKN  (d)
192.168.0.124    3003        0576b32439d  00102/25395   UNKN  (d)
192.168.0.203    3009        6d2d2c004bd  00102/48889   UNKN  (d)
192.168.0.44     3001        342cc3e04e8  00102/26308   UNKN  (d)
192.168.0.124    3003        328b752f3bf  00102/10746   UNKN  (d)
192.168.0.103    3005        7668ba1d5c6  00102/01661   UNKN  (d)
192.168.0.100    3002        6a4e4c120ef  00102/07025   UNKN  (d)
192.168.0.103    3005        22d5db040c7  00102/03719   UNKN  (d)
192.168.0.206    3006        4b80775b4d9  00102/55121   UNKN  (d)
192.168.0.100    3002        79d6b893479  00102/57638   UNKN  (d)
192.168.0.103    3005        1f08524c4b0  00102/28167   UNKN  (d)
192.168.0.103    3005        288fb209320  00102/15231   UNKN  (d)
155 active SIP channel(s)

after 2 hr from restart
* Asterisk CVS-HEAD-07/07/04-23:43:32,

sip.conf :
context = sip           ; Default for incoming calls
;srvlookup = yes                ; Enable SRV lookups on outbound calls
;pedantic = yes                 ; Enable slow, pedantic checking for Pingtel
;tos=lowdelay
;tos=184
;maxexpirey=3600                ; Max length of incoming registration we allow
;defaultexpirey=120             ; Default length of incoming/outoing registratio
n
;notifymimetype=text/plain      ; Allow overriding of mime type in NOTIFY
;videosupport=yes               ; Turn on support for SIP video
disallow=all                    ; Disallow all codecs
allow=ulaw                      ; Allow codecs in order of preference
;;;;allow=alaw
;;;;allow=g723.1
;;;;allow=g729
;;;;allow=gsm
;;;;allow=ilbc
nat=yes


[3001]
type=friend
username=3001
secret=
host=dynamic
defaultip=192.168.0.44
dtmfmode=inband
nat=yes
context=sip
canreinvite=no
reinvite=no
callerid="Op01" <3001>
disallow=all
allow=ulaw
qualify=1000
incominglimit=1
outgoinglimit=1
rtptimeout=60
rtpholdtimeout=300
deny=0.0.0.0/0.0.0.0
permit=192.168.0.44/255.255.255.255


[3002]
type=friend
username=3002
secret=
host=dynamic
defaultip=192.168.0.100
dtmfmode=inband
nat=yes
context=sip
canreinvite=no
reinvite=no
callerid="Op02" <3002>
disallow=all
allow=ulaw
qualify=1000
incominglimit=1
outgoinglimit=1
rtptimeout=60
rtpholdtimeout=300
deny=0.0.0.0/0.0.0.0
permit=192.168.0.100/255.255.255.255
.......
.......
Comments:By: Mark Spencer (markster) 2004-07-13 11:40:01

Restart asterisk, type "sip history", and then wait for them to build up again. When they build up, type "sip show history <foo>" where <foo> is one of the call ID's and paste the resulting history here.  

Also, please confirm you are using latest CVS head.
By: Mark Spencer (markster) 2004-07-13 11:47:14

Also, does the system actually crash?
By: erik123 (erik123) 2004-07-13 12:03:16

5 minutes after restart

LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3005@192.168.0.103 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok
9. CancelDestroy
10. TxReq           ACK sip:3005@192.168.0.103:5060 SIP/2.0
11. Rx              INVITE sip:697413@192.168.0.133 SIP/2.0
12. CancelDestroy
13. TxRespRel       SIP/2.0 503 Unavailable
14. Rx              ACK sip:697413@192.168.0.133 SIP/2.0
LAGI*CLI> sip show history 61a65e286655ed4c6a124ca200e63ea2@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3007@192.168.0.111 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3007@192.168.0.111:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok
9. CancelDestroy
10. TxReq           ACK sip:3007@192.168.0.111:5060 SIP/2.0
11. Rx              BYE sip:528836@192.168.0.133 SIP/2.0
12. TxResp          SIP/2.0 200 OK
LAGI*CLI> sip show history 023ed02d644be54937f2440468da8aa5@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3011@192.168.0.208 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3011@192.168.0.208:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok
9. CancelDestroy
10. TxReq           ACK sip:3011@192.168.0.208:5060 SIP/2.0
11. Rx              INVITE sip:253060@192.168.0.133 SIP/2.0
12. CancelDestroy
13. TxRespRel       SIP/2.0 503 Unavailable
14. Rx              ACK sip:253060@192.168.0.133 SIP/2.0
LAGI*CLI> sip show channels
Peer             User/ANR    Call ID      Seq (Tx/Rx)   Format
192.168.0.44     3001        0b6a578108c  00102/00000   ULAW
192.168.0.206    3006        01bee34c163  00102/00000   ULAW
192.168.0.208    3011        40a3beab068  00102/10127   UNKN  (d)
192.168.0.208    3011        626343eb27e  00102/13273   UNKN  (d)
192.168.0.208    3011        023ed02d644  00102/07418   UNKN  (d)
192.168.0.111    3007        61a65e28665  00102/59624   UNKN  (d)
192.168.0.103    3005        0cc0a7f62fe  00102/41686   UNKN  (d)
7 active SIP channel(s)
LAGI*CLI>
By: twisted (twisted) 2004-07-13 12:36:16

Adjusted severity since it appears this doesn't generate a crash.   If I am mistaken, let me know.
By: erik123 (erik123) 2004-07-13 13:20:18

O.K. but now I have 80 UNKN (d) and * at top RSS 10M
By: twisted (twisted) 2004-07-13 13:27:38

Oops.. .set to minor when should have been major.
By: Mark Spencer (markster) 2004-07-13 17:26:56

This is being triggered by an unusual event -- it's still a bug, but what's causing it to show up on your system and not others is that there is a race in which Asterisk sends INVITE, and then sends CANCEL, then receives the 200 OK on the INVITE (which we then ACK).  In some cases we receive another INVITE, and we send back a 503 unavailable since the line is down.
By: David Svanlund (svanlund) 2004-07-13 18:35:10

I am experiencing the same thing, but to a lesser extent. I have been thinking about why these channels keep showing up, and today I might have found out why. It seems that when the message below occurs, a "dead" (or whatever it is called) channel is being left. I haven't noticed any problems related to this bug, but I'm not running Asterisk in production. I'm updating Asterisk several times per week, so it is a fresh copy.

Jul 14 00:23:06 NOTICE[1133742896]: chan_sip.c:3881 sip_reg_timeout: Registration for 'XXX@XXX' timed out, trying again

It might be unrelated as I haven't examined the problem close, but maybe it could be of some value. My first bug note, so be kind ;-)

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

Additional information after original posting:

Jul 14 01:20:26 NOTICE[1133742896]: chan_sip.c:3871 sip_reg_timeout: Registration for 'XXX@XXX' timed out, trying again
pixel*CLI> sip show channels
Peer             User/ANR    Call ID      Seq (Tx/Rx)   Format
XX.XX.XX.X       XXX         3d1b58ba507  00113/00000   UNKN  (d)
1 active SIP channel(s)

edited on: 07-13-04 18:29
By: Mark Spencer (markster) 2004-07-14 00:20:00

Again, sip history would be helpful here in your example, svanlund.
By: Mark Spencer (markster) 2004-07-14 07:26:28

Erik123: I theorize that this bug in Asterisk is being tripped by a bug in the device Asterisk is calling.  Specifically, my theory is as follows:

1) Asterisk sends INVITE
2) Asterisk receives provisional 100 Trying / 180 Ringing
3) Asterisk sends CANCEL to stop the call
4) Asterisk receives 200 OK to *INVITE* instead of to *CANCEL* -- This is their bug
5) Asterisk sends ACK, which is correct, but we should also send BYE to disconnect it since our CANCEL apparently didn't fly.

I've updated CVS to implement this behavior.  Let me know if this clears it up, and if it doesn't, please supply updated sip history.
By: erik123 (erik123) 2004-07-14 07:47:38

LAGI*CLI> sip show history 53d03c6663d2e6262f1b331f561cb49d@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3004@192.168.0.106 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3004@192.168.0.106:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok
9. CancelDestroy
10. TxReq           ACK sip:3004@192.168.0.106:5060 SIP/2.0
11. Rx              BYE sip:954394@192.168.0.133 SIP/2.0
12. TxResp          SIP/2.0 200 OK
LAGI*CLI>
LAGI*CLI> sip show history 6e5a677603bf5be7198e976d141f7b88@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3003@192.168.0.124 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3003@192.168.0.124:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. ReTx            CANCEL sip:3003@192.168.0.124:5060 SIP/2.0
9. ReTx            CANCEL sip:3003@192.168.0.124:5060 SIP/2.0
10. ReTx            CANCEL sip:3003@192.168.0.124:5060 SIP/2.0
11. Rx              SIP/2.0 200 Ok
12. CancelDestroy
13. TxReq           ACK sip:3003@192.168.0.124:5060 SIP/2.0
14. Rx              BYE sip:790842@192.168.0.133 SIP/2.0
15. TxResp          SIP/2.0 200 OK
LAGI*CLI>
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3011@192.168.0.208 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3011@192.168.0.208:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. ReTx            CANCEL sip:3011@192.168.0.208:5060 SIP/2.0
9. Rx              SIP/2.0 200 Ok
10. CancelDestroy
11. TxReq           ACK sip:3011@192.168.0.208:5060 SIP/2.0
12. Rx              INVITE sip:579351@192.168.0.133 SIP/2.0
13. CancelDestroy
14. TxRespRel       SIP/2.0 503 Unavailable
15. Rx              ACK sip:579351@192.168.0.133 SIP/2.0
LAGI*CLI>
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3005@192.168.0.103 SIP/2.0
2. Rx              SIP/2.0 100 Trying
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing
5. CancelDestroy
6. TxReqRel        CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
7. SchedDestroy    15000 ms
8. ReTx            CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
9. ReTx            CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
10. ReTx            CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
11. ReTx            CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
12. ReTx            CANCEL sip:3005@192.168.0.103:5060 SIP/2.0
13. Rx              SIP/2.0 200 Ok
14. CancelDestroy
15. TxReq           ACK sip:3005@192.168.0.103:5060 SIP/2.0
16. Rx              BYE sip:605979@192.168.0.133 SIP/2.0
17. TxResp          SIP/2.0 200 OK
LAGI*CLI>


I work with X-PRO V2.0 1103g XTEN CO.
By: Mark Spencer (markster) 2004-07-14 07:52:06

Perhaps it would be easier if you found me on IRC.
By: Mark Spencer (markster) 2004-07-14 08:06:37

I've also updated just now CVS to provide some more detail in SIP history which may help confirm or deny my theory.  Please provide a new debug with the new code (should be updated in about 10 minutes to the CVS mirrors).
By: Mark Spencer (markster) 2004-07-16 00:55:46

Please provide updated sip history if this bug still exists.
By: erik123 (erik123) 2004-07-16 01:34:07

Peer             User/ANR    Call ID      Seq (Tx/Rx)   Format
192.168.0.208    3011        7245bc73322  00103/10807   UNKN  (d)
192.168.0.100    3002        0b1ef66d4aa  00102/00000   ULAW
192.168.0.44     3001        46548c873a7  00102/00000   ULAW
192.168.0.208    3011        01c374a6128  00103/11319   UNKN  (d)
192.168.0.100    3002        3ee9e0a821d  00103/54375   UNKN  (d)
192.168.0.208    3011        7b29dce140b  00103/00000   UNKN  (d)
192.168.0.203    3009        7b7ffac5769  00103/00000   UNKN  (d)
192.168.0.203    3009        09fdcb810f5  00103/00000   UNKN  (d)
192.168.0.106    3004        41f95d73694  00103/00000   UNKN  (d)
192.168.0.208    3011        6c870b1b6cc  00103/00794   UNKN  (d)
192.168.0.208    3011        433af6dc516  00103/00000   UNKN  (d)
192.168.0.203    3009        64c71e307e6  00103/00000   UNKN  (d)
192.168.0.208    3011        67aba2cb439  00103/00000   UNKN  (d)
192.168.0.44     3001        5fe68c58624  00103/00000   UNKN  (d)
192.168.0.203    3009        49b62a83669  00103/00000   UNKN  (d)
192.168.0.203    3009        09954908405  00103/00000   UNKN  (d)
192.168.0.206    3006        098f0bdf5c5  00103/00000   UNKN  (d)
192.168.0.208    3011        1650ebaf387  00103/00000   UNKN  (d)
192.168.0.208    3011        4c18a199121  00103/00000   UNKN  (d)
192.168.0.203    3009        3ba987b60ff  00103/00000   UNKN  (d)
192.168.0.203    3009        546d0968679  00103/00000   UNKN  (d)
192.168.0.203    3009        41731b872b8  00103/00000   UNKN  (d)
192.168.0.44     3001        0d2f186d367  00103/00000   UNKN  (d)
192.168.0.208    3011        4bfb722b7f5  00103/00000   UNKN  (d)
192.168.0.208    3011        3c94e58241a  00103/00000   UNKN  (d)
192.168.0.124    3003        7d54a836064  00103/00000   UNKN  (d)
192.168.0.100    3002        25eefb5102d  00103/00000   UNKN  (d)
192.168.0.208    3011        762b49b467b  00103/00000   UNKN  (d)
192.168.0.111    3007        68a09d69116  00103/00000   UNKN  (d)
192.168.0.103    3005        14e9449f0b9  00103/00000   UNKN  (d)
192.168.0.111    3007        6969ce1425a  00103/07007   UNKN  (d)
192.168.0.111    3007        1cb90c2b71a  00103/27725   UNKN  (d)
192.168.0.106    3004        62358c67392  00103/00000   UNKN  (d)
192.168.0.106    3004        06dd40640e6  00103/27747   UNKN  (d)
192.168.0.106    3004        6c11eb39613  00103/00000   UNKN  (d)
192.168.0.111    3007        64a227a542a  00103/43049   UNKN  (d)
192.168.0.106    3004        52b893345c4  00103/23259   UNKN  (d)
192.168.0.124    3003        52c6ca137fd  00103/00000   UNKN  (d)
192.168.0.103    3005        3ab5647052f  00103/00000   UNKN  (d)
192.168.0.106    3004        44e3ef9b0e6  00103/00000   UNKN  (d)
40 active SIP channel(s)
 * SIP Call
1. TxReqRel        INVITE sip:3004@192.168.0.106 SIP/2.0 / 102 INVITE
2. Rx              SIP/2.0 100 Trying / 102 INVITE
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing / 102 INVITE
5. CancelDestroy
6. TxReqRel        CANCEL sip:3004@192.168.0.106:5060 SIP/2.0 / 102 CANCEL
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok / 102 INVITE
9. CancelDestroy
10. TxReq           ACK sip:3004@192.168.0.106:5060 SIP/2.0 / 102 ACK
11. TxReqRel        BYE sip:3004@192.168.0.106:5060 SIP/2.0 / 103 BYE
12. Rx              SIP/2.0 200 Ok / 103 BYE
LAGI*CLI> sip show history 09fdcb810f5442591e159cdf49c0437c@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3009@192.168.0.203 SIP/2.0 / 102 INVITE
2. Rx              SIP/2.0 100 Trying / 102 INVITE
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing / 102 INVITE
5. CancelDestroy
6. TxReqRel        CANCEL sip:3009@192.168.0.203:5060 SIP/2.0 / 102 CANCEL
7. SchedDestroy    15000 ms
8. Rx              SIP/2.0 200 Ok / 102 INVITE
9. CancelDestroy
10. TxReq           ACK sip:3009@192.168.0.203:5060 SIP/2.0 / 102 ACK
11. TxReqRel        BYE sip:3009@192.168.0.203:5060 SIP/2.0 / 103 BYE
12. Rx              SIP/2.0 200 Ok / 103 BYE
LAGI*CLI> sip show history 6c870b1b6cc95e02403a114e1d1926c8@192.168.0.133
LAGI*CLI>
 * SIP Call
1. TxReqRel        INVITE sip:3011@192.168.0.208 SIP/2.0 / 102 INVITE
2. Rx              SIP/2.0 100 Trying / 102 INVITE
3. CancelDestroy
4. Rx              SIP/2.0 180 Ringing / 102 INVITE
5. CancelDestroy
6. TxReqRel        CANCEL sip:3011@192.168.0.208:5060 SIP/2.0 / 102 CANCEL
7. SchedDestroy    15000 ms
8. ReTx            CANCEL sip:3011@192.168.0.208:5060 SIP/2.0
9. Rx              SIP/2.0 200 Ok / 102 INVITE
10. CancelDestroy
11. TxReq           ACK sip:3011@192.168.0.208:5060 SIP/2.0 / 102 ACK
12. TxReqRel        BYE sip:3011@192.168.0.208:5060 SIP/2.0 / 103 BYE
13. Rx              INVITE sip:224894@192.168.0.133 SIP/2.0 / 793 INVITE
14. CancelDestroy
15. Rx              SIP/2.0 200 Ok / 103 BYE
16. Rx              INVITE sip:224894@192.168.0.133 SIP/2.0 / 793 INVITE
17. Rx              INVITE sip:224894@192.168.0.133 SIP/2.0 / 793 INVITE
LAGI*CLI>

Today I have applied new CVS but the problem has remained
By: Olle Johansson (oej) 2004-07-16 02:36:08

Erik: What device are we communicating with? Can you attach a full SIP debug output from your asterisk so we see the whole SIP communication? Please attach it as a file, not inline a bugnote.

Can't figure out from history why we're suddenly sending a CANCEL that the phone doesn't get or understand. After we've sent CANCEL twice, the phone answers 200 OK to a SIP INVITE we've cancelled. That's weird.
The second call seems even more strange, with an INVITE coming in after we've issued a BYE that the phone acknowledged...

Looking forward to the SIP DEBUG....
By: erik123 (erik123) 2004-07-16 09:08:29

oej : I work with X-PRO V2.0 1103g XTEN CO. and I uploaded sipdeb.tgz
Erik123
By: Mark Spencer (markster) 2004-07-16 14:22:09

Clearly we're making progress.  My assertion about the cause of the bug is in fact correct -- they send 200 OK for the INVITE and not for the CANCEL, and further, Asterisk IS doing the right thing by sending the ACK and then the BYE.  

However, the call still remains.  My reading is that we're using the 200 OK to ack the CANCEL instead of acking the INVITE as we should be.  That leaves the INVITE still pending out there in limbo, because we're awaiting the 487 to come back on it.

So, instead I've modified Asterisk now to (hopefully) properly apply this ACK only to the 200 OK to the INVITE and continue retransmission of the CANCEL.  The result should be that Asterisk will continue to retransmit (and eventually timeout on sending) the CANCEL.

If this doesn't solve it, it would be helpful if you would find me on IRC so I can login and try to debug this last part and get this bug resolved.

Once we have fixed the bugs on the Asterisk side, I would strongly suggest contacting XTen to get them to fix their soft phone as well, but please don't do it until the Asterisk side is fixed because without Xten's broken CANCEL handling,
By: Mark Spencer (markster) 2004-07-16 22:08:50

Please let me know as soon as possible.
By: Mark Spencer (markster) 2004-07-17 16:28:48

I'm going to assume this to be fixed, you can reopen it if it isn't.