jamesj@firehouse ~/src/shtoom $ scripts/shtoomphone.py
2006-06-14T12:03:56.359962 [-] Log opened.
2006-06-14T12:03:56.553682 [-] <class 'shtoom.sip.SipProtocol'> starting on 50602006-06-14T12:03:56.554295 [-] Starting protocol <shtoom.sip.SipProtocol object at 0xb79d540c>
2006-06-14T12:03:56.554645 [app] sip listener installed on 5060
2006-06-14T12:03:56.555119 [nat] NAT preference says to use both (both)
2006-06-14T12:03:56.640077 [-] <class 'shtoom.upnp.UPnPProtocol'> starting on 1900
2006-06-14T12:03:56.643284 [-] Starting protocol <shtoom.upnp.UPnPProtocol object at 0xb7906d0c>
2006-06-14T12:03:56.645163 [-] <class 'shtoom.stun._DetectSTUNProt'> starting on 0
2006-06-14T12:03:56.645756 [-] Starting protocol <shtoom.stun._DetectSTUNProt object at 0xb78c598c>
2006-06-14T12:03:56.646327 [phone] Getting new audio device
2006-06-14T12:03:56.713262 [-] audioPref is oss
2006-06-14T12:03:56.713717 [-] ossaudiodev opening default device
2006-06-14T12:03:56.789489 [-] Got new audio device <MediaLayer wrapped around <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c>> :: <type 'instance'>2006-06-14T12:03:56.790033 [sip] no outstanding registrations, registering
2006-06-14T12:03:56.931603 [-] done
2006-06-14T12:03:56.933777 [-] twisted.internet.protocol.DatagramProtocol starting on 0
2006-06-14T12:03:56.934386 [-] Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0xb78fb8ac>
2006-06-14T12:03:57.043926 [-] (Port 0 Closed)
2006-06-14T12:03:57.044433 [-] Stopping protocol <twisted.internet.protocol.DatagramProtocol instance at 0xb78fb8ac>
2006-06-14T12:03:57.047134 [shtoom.sip.SipProtocol (UDP)] checking for cached creds for asterisk: ('200', '200') (retry False)
2006-06-14T12:03:57.047982 [shtoom.sip.SipProtocol (UDP)] auth 200:asterisk:200 bf33f57c4a2052abd017e431622174d1 a1099da631424249b280197e3193f5c2
2006-06-14T12:03:57.175945 [stun] got STUN response to None from ('64.69.76.23', 3478)
2006-06-14T12:03:57.177557 [stun] STUN: unhandled AV (Unknown type -7fe0), val '\'\\x00\\x01\\xdeO\\xdf\\x94Y"\''
2006-06-14T12:03:57.177978 [stun] STUN: unhandled AV (Unknown type -7fde), val "'Vovida.org 0.96\\x00'"
2006-06-14T12:03:57.304034 [stun] got STUN response to '941a7aa8df99e93452d61575a67c82c' from ('64.69.76.24', 3479)
2006-06-14T12:03:57.304422 [stun] STUN: unhandled AV (Unknown type -7fe0), val '\'\\x00\\x01\\x15"\\x14\\xf9\\x01\\xb0\''
2006-06-14T12:03:57.304585 [stun] STUN: unhandled AV (Unknown type -7fde), val "'Vovida.org 0.96\\x00'"
2006-06-14T12:03:57.305985 [-] (Port 0 Closed)
2006-06-14T12:03:57.306282 [-] Stopping protocol <shtoom.stun._DetectSTUNProt object at 0xb78c598c>
2006-06-14T12:04:02.236290 [-] **** Calling app.placeCall on  sip:4321@sur-pbx
2006-06-14T12:04:02.236735 [-] **** RESULT: Deferred is  None
2006-06-14T12:04:02.241966 [-] *** PHONE.PY PLACECALL: Starting for  sip:4321@sur-pbx
2006-06-14T12:04:02.243743 [-] ** SIP.PY PLACECALL: No Failures, returning  <Deferred at 0xB78F68CCL>
2006-06-14T12:04:02.244046 [-] *** PHONE.PY PLACECALL: Returning  <Deferred at 0xB78F68CCL>
2006-06-14T12:04:02.250353 [-] twisted.internet.protocol.DatagramProtocol starting on 0
2006-06-14T12:04:02.250783 [-] Starting protocol <twisted.internet.protocol.DatagramProtocol instance at 0xb788b06c>
2006-06-14T12:04:02.253917 [-] dialog is <Dialog "200" <sip:200>;tag=0285007a->sip:4321@sur-pbx, 400988305@128.227.123.24>
2006-06-14T12:04:02.259273 [-] shtoom.rtp.protocol.RTPProtocol starting on 185702006-06-14T12:04:02.259719 [-] Starting protocol <shtoom.rtp.protocol.RTPProtocol instance at 0xb788b1cc>
2006-06-14T12:04:02.259943 [-] shtoom.rtp.rtcp.RTCPProtocol starting on 18571
2006-06-14T12:04:02.260181 [-] Starting protocol <shtoom.rtp.rtcp.RTCPProtocol instance at 0xb788b2ac>
2006-06-14T12:04:02.260538 [-] sendinvite setting cookie to CallCookie1
2006-06-14T12:04:02.266511 [audio] audio device <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c> close
2006-06-14T12:04:02.266822 [-] baseaudio CLOSE False
2006-06-14T12:04:02.266967 [-] ossaudiodev closing
2006-06-14T12:04:02.349574 [sip] Sending INVITE to ('128.227.252.13', 5060):
        INVITE sip:4321@sur-pbx SIP/2.0
        CSeq: 2981 INVITE
        To: sip:4321@sur-pbx
        Content-Type: application/sdp
        From: "200" <sip:200>;tag=0285007a
        Call-ID: 400988305@128.227.123.24
        Subject: sip:200
        Allow-Events: telephone-event
        User-Agent: Shtoom/0.3alpha0
        Contact: sip:200@128.227.123.24:5060
        Content-Length: 201
        Via: SIP/2.0/UDP 128.227.123.24:5060;branch=z9hG4bK916c00281bd0614ca7f6abf79df98714;rport

        v=0
        o=root 4226 4226 IN IP4 128.227.123.24
        s=shtoom
        c=IN IP4 128.227.123.24
        t=0 0
        m=audio 18570 RTP/AVP 0 13 101
        a=rtpmap:0 PCMU/8000/1
        a=rtpmap:13 CN/8000/1
        a=rtpmap:101 telephone-event/8000

2006-06-14T12:04:02.355107 [-] Unhandled error in Deferred:
2006-06-14T12:04:02.355363 [-] Traceback (most recent call last):
          File "/usr/lib/python2.4/threading.py", line 422, in run
            self.__target(*self.__args, **self.__kwargs)
          File "/usr/lib/python2.4/site-packages/twisted/internet/posixbase.py", line 199, in run
            self.mainLoop()
          File "/usr/lib/python2.4/site-packages/twisted/internet/posixbase.py", line 207, in mainLoop
            self.runUntilCurrent()
          File "/usr/lib/python2.4/site-packages/twisted/internet/base.py", line 533, in runUntilCurrent
            call.func(*call.args, **call.kw)
        --- <exception caught here> ---
          File "/usr/lib/python2.4/site-packages/twisted/internet/task.py", line 84, in __call__
            self.f(*self.a, **self.kw)
          File "/home/jamesj/src/shtoom/shtoom/audio/ossaudio.py", line 49, in _push_up_some_data
            data = self.dev.read(320*self._channels)
        exceptions.AttributeError: 'NoneType' object has no attribute 'read'

2006-06-14T12:04:02.358745 [-] (Port 0 Closed)
2006-06-14T12:04:02.358976 [-] Stopping protocol <twisted.internet.protocol.DatagramProtocol instance at 0xb788b06c>
2006-06-14T12:04:02.360165 [sip] Handling 407 while in state SENT_INVITE
2006-06-14T12:04:02.360404 [sip] sending Ack for a 407
2006-06-14T12:04:02.360687 [shtoom.sip.SipProtocol (UDP)] correcting local port to 5060
2006-06-14T12:04:02.361714 [sip] sending ACK to 128.227.252.13 5060
2006-06-14T12:04:02.362340 [sip] sending ACK to ('128.227.252.13', 5060)
        ACK sip:4321@sur-pbx SIP/2.0
        CSeq: 2981 ACK
        To: sip:4321@sur-pbx;tag=as5f8dcefb
        From: "200" <sip:200>;tag=0285007a
        Call-ID: 400988305@128.227.123.24
        Allow-Events: telephone-event
        User-Agent: Shtoom/0.3alpha0
        Content-Length: 0
        Via: SIP/2.0/UDP 128.227.123.24:5060;branch=z9hG4bK916c00281bd0614ca7f6abf79df98714;rport


2006-06-14T12:04:02.362783 [shtoom.sip.SipProtocol (UDP)] checking for cached creds for asterisk: ('200', '200') (retry False)
2006-06-14T12:04:02.363321 [shtoom.sip.SipProtocol (UDP)] auth 200:asterisk:200 bf33f57c4a2052abd017e431622174d1 e09cc879ca7ebb51810bfa3c7056ced9
2006-06-14T12:04:02.364479 [audio] audio device <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c> close
2006-06-14T12:04:02.364716 [shtoom.sip.SipProtocol (UDP)] baseaudio CLOSE True
2006-06-14T12:04:02.367489 [sip] Sending INVITE to ('128.227.252.13', 5060):
        INVITE sip:4321@sur-pbx SIP/2.0
        CSeq: 2982 INVITE
        To: sip:4321@sur-pbx;tag=as5f8dcefb
        Content-Type: application/sdp
        From: "200" <sip:200>;tag=0285007a
        Call-ID: 400988305@128.227.123.24
        Subject: sip:200
        Allow-Events: telephone-event
        User-Agent: Shtoom/0.3alpha0
        Proxy-Authorization: Digest username="200", realm="asterisk", nonce="7260638a", uri="sip:4321@sur-pbx", response="e09cc879ca7ebb51810bfa3c7056ced9"
        Contact: sip:200@128.227.123.24:5060
        Content-Length: 201
        Via: SIP/2.0/UDP 128.227.123.24:5060;branch=z9hG4bKc02181b9042bc3404e980eab4659fff5;rport

        v=0
        o=root 4236 4236 IN IP4 128.227.123.24
        s=shtoom
        c=IN IP4 128.227.123.24
        t=0 0
        m=audio 18570 RTP/AVP 0 13 101
        a=rtpmap:0 PCMU/8000/1
        a=rtpmap:13 CN/8000/1
        a=rtpmap:101 telephone-event/8000

2006-06-14T12:04:02.372611 [sip] Handling 100 while in state SENT_INVITE
2006-06-14T12:04:02.382429 [sip] Handling 200 while in state SENT_INVITE
2006-06-14T12:04:02.383228 [shtoom.sip.SipProtocol (UDP)] oksdp <shtoom.sdp.SDP instance at 0xb789db2c>
2006-06-14T12:04:02.383942 [audio] audio device <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c> close
2006-06-14T12:04:02.384147 [shtoom.sip.SipProtocol (UDP)] baseaudio CLOSE True
2006-06-14T12:04:02.384542 [shtoom.sip.SipProtocol (UDP)] correcting local port to 5060
2006-06-14T12:04:02.385601 [sip] sending ACK to 128.227.252.13 5060
2006-06-14T12:04:02.385786 [shtoom.sip.SipProtocol (UDP)] startCall reopening None <MediaLayer wrapped around <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c>>
2006-06-14T12:04:02.385942 [shtoom.sip.SipProtocol (UDP)] call Start 'CallCookie1' ('128.227.252.13', 10584)
2006-06-14T12:04:02.386230 [rtp] sending CN(0) to seed firewall to 128.227.252.13:10584
2006-06-14T12:04:02.386576 [audio] audio device <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c> close
2006-06-14T12:04:02.386799 [shtoom.sip.SipProtocol (UDP)] baseaudio CLOSE True
2006-06-14T12:04:02.387128 [shtoom.sip.SipProtocol (UDP)] baseaudio REOPEN True
2006-06-14T12:04:02.387315 [shtoom.sip.SipProtocol (UDP)] ossaudiodev opening default device
2006-06-14T12:04:02.450572 [shtoom.sip.SipProtocol (UDP)] startCall opened 'CallCookie1' <MediaLayer wrapped around <shtoom.audio.ossaudio.OSSAudioDevice object at 0xb78cad0c>>
2006-06-14T12:04:02.451723 [sip] sending ACK to ('128.227.252.13', 5060)
        ACK sip:4321@sur-pbx;tag=as5f8dcefb SIP/2.0
        CSeq: 2982 ACK
        To: sip:4321@sur-pbx;tag=as5f8dcefb
        From: "200" <sip:200>;tag=0285007a
        Call-ID: 400988305@128.227.123.24
        Allow-Events: telephone-event
        User-Agent: Shtoom/0.3alpha0
        Content-Length: 0
        Via: SIP/2.0/UDP 128.227.123.24:5060;branch=z9hG4bK75a1ba8c50f9a2230236b36a631821fa;rport


2006-06-14T12:04:02.645343 [UPnP] discovery timed out
2006-06-14T12:04:02.645670 [UPnP] no UPnP found!
2006-06-14T12:04:02.645972 [nat] detectNAT got [(True, None), (True, <NatType None>)]
2006-06-14T12:04:02.646113 [nat] using STUN mapper
2006-06-14T12:04:02.778526 [stun] got STUN response to None from ('64.69.76.23', 3478)
2006-06-14T12:04:02.778868 [stun] STUN: unhandled AV (Unknown type -7fe0), val "'\\x00\\x011\\xa4\\xa2\\x83\\x81\\xb3'"
2006-06-14T12:04:02.779024 [stun] STUN: unhandled AV (Unknown type -7fde), val "'Vovida.org 0.96\\x00'"
2006-06-14T12:04:02.796424 [sip] late stun packet, ignoring
2006-06-14T12:04:02.885274 [sip] late stun packet, ignoring
2006-06-14T12:04:02.897935 [sip] late stun packet, ignoring
2006-06-14T12:04:22.937154 [-] stopping SIP, and unmapping it (True)
2006-06-14T12:04:22.937557 [-] unmapping sip using <shtoom.stun.STUNMapper instance at 0xb789950c>
2006-06-14T12:04:22.938319 [shtoom.upnp.UPnPProtocol (UDP)] (Port 1900 Closed)
2006-06-14T12:04:22.938533 [shtoom.upnp.UPnPProtocol (UDP)] Stopping protocol <shtoom.upnp.UPnPProtocol object at 0xb7906d0c>
2006-06-14T12:04:22.939257 [shtoom.rtp.protocol.RTPProtocol (UDP)] (Port 18570 Closed)
2006-06-14T12:04:22.939496 [shtoom.rtp.protocol.RTPProtocol (UDP)] Stopping protocol <shtoom.rtp.protocol.RTPProtocol instance at 0xb788b1cc>
2006-06-14T12:04:22.939765 [shtoom.rtp.rtcp.RTCPProtocol (UDP)] (Port 18571 Closed)
2006-06-14T12:04:22.939979 [shtoom.rtp.rtcp.RTCPProtocol (UDP)] Stopping protocol <shtoom.rtp.rtcp.RTCPProtocol instance at 0xb788b2ac>
2006-06-14T12:04:23.027129 [-] (Port 5060 Closed)
2006-06-14T12:04:23.027438 [-] Stopping protocol <shtoom.sip.SipProtocol object at 0xb79d540c>
2006-06-14T12:04:23.028202 [-] output device ran dry unnecessarily! now: 20.578, self.drytime: 20.5302569866, nextseq: 46929, newsampseqno: None
2006-06-14T12:04:23.028879 [-] Main loop terminated.