0

Failing to receive SMS, script never called?

I just set up a fresh number for some testing, it claims to support voice + text, I send a message to it from my personal phone and... no joy.

Looking at the logs (one of my many failures below), I see only one error, about a negotiation being declined, and not even a basic log("hello world") is showing up, so it seems to me something is failing before my script gets executed.

Any suggestions?

Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#GW-SMS#: Located applicationId[5066393]Address[14422225039]={startUrl=http://hosting.tropo.com/5050015/www/testscript.js, ODF=c} for key [14422225039] #[N/A][N/A][N/A][N/A][?][?][smss_tpq1am96wme6]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#GW-SMS#: Located [10.108.198.90] for number [14422225039] as target. #[N/A][N/A][N/A][N/A][?][?][smss_tpq1am96wme6]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#GW-SMS#: Will send INVITE to tropo[10.108.198.90] to init SMS session #[N/A][N/A][N/A][N/A][?][?][smss_tpq1am96wme6]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#SIP#: Application session creating: sas_2-15-sm15wds5d8k1mhyTropoSBCRouter #[N/A][N/A][N/A][N/A][?][?]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] will expired after 14400000
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#SIP#: Session creating: ss_r1ghikhrirkx #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/0/[ReceiverDaemon]/#SIP#: SetRoutingDirective: NEW #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[ReceiverDaemon]/#GW-SMS#: SipSMSSession [id=smss_tpq1am96wme6,localParty=14422225039, remoteParty=1MyPhoneNumber, valid=true, readyToSendMessage=false, sipSessionId=ss_r1ghikhrirkx, _network=null] is associated with: SipApplicationSessionAdaptor[appSessionId=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90][smss_tpq1am96wme6]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[ReceiverDaemon]/#SIP#: (o)[INVITE sip:4422225039@10.108.198.90 SIP/2.0\r\nContent-Length: 4\r\nCSeq: 1 INVITE\r\nContact: <sip:198.11.254.102:5060;transport=udp>\r\nCall-ID: 1tcjmumh0syh\r\nx-sid: 2be62206ee2aa40603c77866203fac8b\r\nMax-Forwards: 70\r\nFrom: <sip:MyPhoneNumber@10.108.198.90;real-id=1MyPhoneNumber>;tag=18ciluprfzs9b\r\nContent-Type: text/plain\r\nTo: <sip:4422225039@10.108.198.90;real-id=14422225039>\r\nx-tropo-sms: true\r\nVia: SIP/2.0/UDP 198.11.254.102:5060;branch=z9hG4bK13x0295w01szb;rport\r\n\r\nGrrr] #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[ReceiverDaemon]/#SIP#: Send message to: /10.108.198.90:5060 by udp #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.385 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[ReceiverDaemon]/#SIP#: Connected to 10.108.198.90:5060/udp #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.386 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] will expired after 14400000
Aug 24 03:02:32.386 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-11]/#SIP#: Timer processInvalidationWhenReady fired #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.386 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-11]/#SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.386 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-11]/#SIP#: processInvalidationWhenReady [ss_r1ghikhrirkx], current State = INITIAL, Vaild:true, Role:UAC, hasOngoingTransaction: true, OT: 1, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.386 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-11]/#SIP#: processInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.388 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] will expired after 14400000
Aug 24 03:02:32.388 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-12]/#SIP#: Timer processInvalidationWhenReady fired #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.388 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-12]/#SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.388 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-12]/#SIP#: processInvalidationWhenReady [ss_r1ghikhrirkx], current State = INITIAL, Vaild:true, Role:UAC, hasOngoingTransaction: true, OT: 1, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.388 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-12]/#SIP#: processInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.391 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] will expired after 14400000
Aug 24 03:02:32.391 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-13]/#SIP#: Timer processInvalidationWhenReady fired #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.391 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-13]/#SIP#: ProcessSipSessionsInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.391 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-13]/#SIP#: processInvalidationWhenReady [ss_r1ghikhrirkx], current State = EARLY, Vaild:true, Role:UAC, hasOngoingTransaction: true, OT: 1, ProcessingByApp: false, Fresh:false, invalidateWhenReady: true #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.391 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-13]/#SIP#: processInvalidationWhenReady [sas_2-15-sm15wds5d8k1mhyTropoSBCRouter], invalidateWhenReady: true
Aug 24 03:02:32.412 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: (o)[ACK sip:4422225039@10.108.198.90 SIP/2.0\r\nContent-Length: 0\r\nCSeq: 1 ACK\r\nCall-ID: 1tcjmumh0syh\r\nMax-Forwards: 70\r\nFrom: <sip:MyPhoneNumber@10.108.198.90;real-id=1MyPhoneNumber>;tag=18ciluprfzs9b\r\nTo: <sip:4422225039@10.108.198.90;real-id=14422225039>;tag=ufasb5nkm40x\r\nVia: SIP/2.0/UDP 198.11.254.102:5060;branch=z9hG4bK13x0295w01szb;rport\r\n\r\n] #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90]
Aug 24 03:02:32.412 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: Send message to: /10.108.198.90:5060 by udp #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90][sip:MyPhoneNumber@10.108.198.90]
Aug 24 03:02:32.412 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: Connected to 10.108.198.90:5060/udp #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90]
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] will expired after 14400000
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#GW-SMS#: Finding SMSSession for SessionKey [local=14422225039, remote=1MyPhoneNumber] #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#GW-SMS#: SipSMSSession [id=smss_tpq1am96wme6,localParty=14422225039, remoteParty=1MyPhoneNumber, valid=true, readyToSendMessage=false, sipSessionId=ss_r1ghikhrirkx, _network=null] got error when negotiating[SIP/2.0 603 Decline\r\nContent-Length: 0\r\nCSeq: 1 INVITE\r\nCall-ID: 1tcjmumh0syh\r\nFrom: <sip:MyPhoneNumber@10.108.198.90;real-id=1MyPhoneNumber>;tag=18ciluprfzs9b\r\nTo: <sip:4422225039@10.108.198.90;real-id=14422225039>;tag=ufasb5nkm40x\r\nVia: SIP/2.0/UDP 198.11.254.102:5060;branch=z9hG4bK13x0295w01szb;rport=5060;received=10.108.198.74\r\n\r\n] #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)][smss_tpq1am96wme6]
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#GW-SMS#: SipSMSSession [id=smss_tpq1am96wme6,localParty=14422225039, remoteParty=1MyPhoneNumber, valid=true, readyToSendMessage=false, sipSessionId=ss_r1ghikhrirkx, _network=null] is invalidating. #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)][smss_tpq1am96wme6]
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipApplicationSessionImpl[_state=VALID, _id=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, ] is invalidating. (as)
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[udp/0.0.0.0/5060-t-4]/#SIP#: SipSessionImpl[_id=ss_r1ghikhrirkx, _parentId=sas_2-15-sm15wds5d8k1mhyTropoSBCRouter, _handler=TropoSMSDriverServlet, _state=INITIAL, _fresh=false, _valid=true, _unavailable=false, _role=UAC, _method=INVITE, _callId=1tcjmumh0syh, ] is invalidating. (s) #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]
Aug 24 03:02:32.413 gw2.prod.wdc.sl.tropo.com PRISM 5050015/5066393/2be62206ee2aa40603c77866203fac8b/2be62206ee2aa40603c77866203fac8b/1/1tcjmumh0syh/[Timer-15]/#SIP#: Timer processInvalidationWhenReady fired #[TropoSBCRouter][sas_2-15-sm15wds5d8k1mhyTropoSBCRouter][1tcjmumh0syh][ss_r1ghikhrirkx][sip:4422225039@10.108.198.90(10.108.198.90:5060)][sip:MyPhoneNumber@10.108.198.90(198.11.254.102:5060)]

6 comments

Please sign in to leave a comment.