[Freeswitch-users] [USER_NOT_REGISTERED] after Answer

[Peter Steinbach]

Hello,

I have a strange phenomenon with a phone (snomM700 DECT) behind NAT:

  * phone 43 is ringing (local IP is 192.168.0.56, remote IP is
    195.71.aaa.bbb (anonymized)
  * phone 43 is answering the call
  * we immediately get [USER_NOT_REGISTERED]

Register string is as follows
<sip:43 at 192.168.0.56:1506
0;line=7045;fs_nat=yes;fs_path=sip:43 at 195.71.aaa.bbb:5060;line=7045>

Here is the Freeswitch log starting with phone's SDP:

3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
sofia.c:6760 Remote SDP:
3c74476e-1ce3-46d0-874d-e75bbebce8ce v=0
3c74476e-1ce3-46d0-874d-e75bbebce8ce o=43 4408 4408 IN IP4 195.71.aaa.bbb
3c74476e-1ce3-46d0-874d-e75bbebce8ce s=-
3c74476e-1ce3-46d0-874d-e75bbebce8ce c=IN IP4 195.71.aaa.bbb
3c74476e-1ce3-46d0-874d-e75bbebce8ce t=0 0
3c74476e-1ce3-46d0-874d-e75bbebce8ce a=sendrecv
3c74476e-1ce3-46d0-874d-e75bbebce8ce m=audio 50030 RTP/AVP 8
3c74476e-1ce3-46d0-874d-e75bbebce8ce a=rtpmap:8 PCMA/8000
3c74476e-1ce3-46d0-874d-e75bbebce8ce a=ptime:20
3c74476e-1ce3-46d0-874d-e75bbebce8ce a=maxptime:80
3c74476e-1ce3-46d0-874d-e75bbebce8ce a=rtcp:50031
3c74476e-1ce3-46d0-874d-e75bbebce8ce
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
sofia.c:6750 Channel sofia/internal/43 at 192.168.0.56:15060 entering state
[ready][200]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4150 Audio Codec Compare
[PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4205 Audio Codec Compare [PCMA:8:8000:20:64000:1]
++++ is saved as a match
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4150 Audio Codec Compare
[PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4150 Audio Codec Compare
[PCMA:8:8000:20:64000:1]/[SPEEX:99:8000:20:24600:1]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4150 Audio Codec Compare
[PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4150 Audio Codec Compare
[PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:2897 Set Codec sofia/internal/43 at 192.168.0.56:15060
PCMA/8000 20 ms 160 samples 64000 bits 1 channels
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_codec.c:111 sofia/internal/43 at 192.168.0.56:15060 Original
read codec set to PCMA:8
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:4472 No 2833 in SDP.  Disable 2833 dtmf and switch
to INFO
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:6019 AUDIO RTP
[sofia/internal/43 at 192.168.0.56:15060] 144.76.47.185 port 12664 ->
195.71.aaa.bbb port 50030 codec: 8 ms: 20
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_rtp.c:3753 Starting timer [soft] 160 bytes per 20ms
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:6237 Activating RTCP PORT 50031
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_rtp.c:4132 RTCP send rate is: 5000 and packet rate is: 20000
Remote Port: 50031
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_rtp.c:2443 Setting RTCP remote addr to 195.71.aaa.bbb:50031 2
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [DEBUG]
switch_core_media.c:6348 sofia/internal/43 at 192.168.0.56:15060 Set rtp
dtmf delay to 40
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.585575 [NOTICE]
sofia.c:7714 Channel [sofia/internal/43 at 192.168.0.56:15060] has been
answered
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.605579 [DEBUG]
switch_channel.c:3757 (sofia/internal/43 at 192.168.0.56:15060) Callstate
Change RINGING -> ACTIVE
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.625571 [NOTICE]
switch_ivr_bridge.c:1416 Hangup sofia/internal/43 at 192.168.0.56:15060
[CS_CONSUME_MEDIA] [USER_NOT_REGISTERED]
3c74476e-1ce3-46d0-874d-e75bbebce8ce 2015-11-19 15:46:38.625571 [DEBUG]
switch_ivr_bridge.c:1689 sofia/internal/43 at 192.168.0.56:15060 skip
receive message [UNBRIDGE] (channel is hungup already)

Anybody has a clue where this may come from? Freeswitch is rather new
(from 03-Nov-2015).

-- 
With kind regards
Peter Steinbach 

Telefaks Services GmbH
mailto:lists (att) telefaks.de
Internet: www.telefaks.de

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20151119/f82bea01/attachment.html