[Shtoom] bug report with detailed logs

[zooko at zooko.com]

Shtoom appears to be getting its packet order mixed up.  tethereal says this is what happened:

  1   0.000000 192.168.1.101 -> 192.98.81.87 STUN Message : Binding Request
  2   0.177187 192.98.81.87 -> 192.168.1.101 STUN Message : Binding Response
  3   0.192145 192.168.1.101 -> 192.246.69.223 SIP Request: REGISTER sip:479317 at fwd.pulver.com
  4   0.246508 192.246.69.223 -> 192.168.1.101 SIP Status: 401 Unauthorized    (0 bindings)
  5   0.292164 192.168.1.101 -> 192.246.69.223 SIP Request: REGISTER sip:479317 at fwd.pulver.com
  6   0.346071 192.246.69.223 -> 192.168.1.101 SIP Status: 200 OK    (2 bindings)

Shtoom's debug log is appended, but the relevant snippets look like this, and
appeared in this order in the log window:

14:07:58: register sent
REGISTER sip:479317 at fwd.pulver.com SIP/2.0
...
14:07:58: got SIP response
 SIP/2.0 200 OK
...
14:07:58: got SIP response 200: OK
14:07:58: SIP PACKET
SIP/2.0 200 OK
...
14:07:58: Got a SIP packet from 192.246.69.223:5060
14:07:58: register sent
REGISTER sip:479317 at fwd.pulver.com SIP/2.0
...
14:07:58: got SIP response
 SIP/2.0 401 Unauthorized
...
14:07:58: got SIP response 401: Unauthorized
14:07:58: SIP PACKET
SIP/2.0 401 Unauthorized
...
14:07:58: Got a SIP packet from 192.246.69.223:5060


After this, Shtoom is in the "I think I'm unregistered" state.  If I try to
make a call, it will go into "I'm calling" state but do nothing.  When I try to
hang up that call, it will give an internal error.


This is with the wx GUI.  Perhaps the separate-thread-for-wx-GUI is getting
involved.


Regards,

Zooko

full log window contents appended

14:07:58: register sent
REGISTER sip:479317 at fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 24.222.141.10:5060
CSeq: 1226 REGISTER
To: sip:479317 at fwd.pulver.com
From: sip:479317 at fwd.pulver.com
Expires: 900
Call-ID: 400571354 at 24.222.141.10
User-Agent: Shtoom/0.3alpha0
Contact: <sip:479317 at 24.222.141.10:5060>
Content-Length: 0


14:07:58: got SIP response
 SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.101:5060
CSeq: 1227 REGISTER
To: sip:479317 at fwd.pulver.com;tag=ec5154884c15db89cef5049aa4f06328.356e
From: sip:479317 at fwd.pulver.com
Call-ID: 400571354 at 24.222.141.10
Contact: <sip:479317 at 192.168.1.101:5060>;q=0.00;expires=1517
Contact: <sip:479317 at 24.222.141.10:5060>;q=0.00;expires=900
Server: Sip EXpress router (0.8.12 (i386/linux))
Content-Length: 0


14:07:58: got SIP response 200: OK
14:07:58: SIP PACKET
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.101:5060
CSeq: 1227 REGISTER
To: sip:479317 at fwd.pulver.com;tag=ec5154884c15db89cef5049aa4f06328.356e
From: sip:479317 at fwd.pulver.com
Call-ID: 400571354 at 24.222.141.10
Contact: <sip:479317 at 192.168.1.101:5060>;q=0.00;expires=1517
Contact: <sip:479317 at 24.222.141.10:5060>;q=0.00;expires=900
Server: Sip EXpress router (0.8.12 (i386/linux))
Content-Length: 0


14:07:58: Got a SIP packet from 192.246.69.223:5060
14:07:58: register sent
REGISTER sip:479317 at fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP 24.222.141.10:5060
CSeq: 1227 REGISTER
To: sip:479317 at fwd.pulver.com
From: sip:479317 at fwd.pulver.com
Expires: 900
Call-ID: 400571354 at 24.222.141.10
Authorization: Digest username="479317", realm="fwd.pulver.com", nonce="4149d7ab75021957dd37fd9002259a1b2eedefef", uri="sip:479317 at fwd.pulver.com", response="70b9ec7bac7914ed4b93e8507a197276"
User-Agent: Shtoom/0.3alpha0
Contact: <sip:479317 at 24.222.141.10:5060>
Content-Length: 0


14:07:58: got SIP response
 SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 24.222.141.10:5060
CSeq: 1226 REGISTER
To: sip:479317 at fwd.pulver.com;tag=ec5154884c15db89cef5049aa4f06328.356e
From: sip:479317 at fwd.pulver.com
Call-ID: 400571354 at 24.222.141.10
WWW-Authenticate: Digest realm="fwd.pulver.com", nonce="4149d7ab75021957dd37fd9002259a1b2eedefef"
Server: Sip EXpress router (0.8.12 (i386/linux))
Content-Length: 0


14:07:58: got SIP response 401: Unauthorized
14:07:58: SIP PACKET
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 24.222.141.10:5060
CSeq: 1226 REGISTER
To: sip:479317 at fwd.pulver.com;tag=ec5154884c15db89cef5049aa4f06328.356e
From: sip:479317 at fwd.pulver.com
Call-ID: 400571354 at 24.222.141.10
WWW-Authenticate: Digest realm="fwd.pulver.com", nonce="4149d7ab75021957dd37fd9002259a1b2eedefef"
Server: Sip EXpress router (0.8.12 (i386/linux))
Content-Length: 0


14:07:58: Got a SIP packet from 192.246.69.223:5060