[Freeswitch-users] Help on reading the log better

4 Aug 2010

      Hi,

I've finished the book, and was able to send a call through to another
switch that we use.  There was an initial codec mismatch (G729), but after
reading the debug logs (fs_cli /log 7), it was identified and after fixing
that, the call went through just fine.

Today, I was trying some more changes on the default config, and the call
will not go through.  While that is not a problem as I can always go back to
the default conf, what was bothering me is that I could not find out the
right cause by reading the logs.  The call also did not hit the other
switch.  Perhaps I am not reading something right.  Can someone please help
me identify what part of the logs below are showing where the calls are
failing?

The log is given below my signature.  I changed my IPs and dialed number.
 Sorry for the inconvenience.

Regards
HASSAN

2010-08-04 13:06:47.459004 [DEBUG] sofia.c:6000 IP 192.168.254.10 Rejected
by acl "domains". Falling back to Digest auth.
2010-08-04 13:06:48.853933 [DEBUG] sofia.c:6000 IP 192.168.254.10 Rejected
by acl "domains". Falling back to Digest auth.
2010-08-04 13:06:48.855161 [NOTICE] switch_channel.c:779 New Channel
sofia/internal/hassan@a.b.c.d [3b01cb99-20dd-4a9d-8084-2f2e16a5aee6]
2010-08-04 13:06:48.855161 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_NEW
2010-08-04 13:06:48.855161 [DEBUG] switch_core_state_machine.c:320
(sofia/internal/hassan@a.b.c.d) State NEW
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:6823 Setting NAT mode based on
nat.auto
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4318 Channel
sofia/internal/hassan@a.b.c.d entering state [received][100]
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4329 Remote SDP:
v=0
o=- 9 2 IN IP4 192.168.254.10
s=CounterPath Bria
c=IN IP4 192.168.254.10
t=0 0
m=audio 63242 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 2 : wsPFY2UY ge45TD7O a1.b1.c1.d1 63242
a=alt:2 1 : mCzsWRNJ nH/GgDGG 192.168.254.10 63242
a=x-rtp-session-id:C59D45BA9189497CB4C041AC656702E2

2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:3845 Audio Codec Compare
[G729:18:8000:20]/[G729:18:8000:20]
2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:2442 Set Codec
sofia/internal/hassan@a.b.c.d G729/8000 20 ms 160 samples
2010-08-04 13:06:48.856895 [DEBUG] sofia_glue.c:3941 Set 2833 dtmf send/recv
payload to 101
2010-08-04 13:06:48.856895 [DEBUG] sofia.c:4476
(sofia/internal/hassan@a.b.c.d) State Change CS_NEW -> CS_INIT
2010-08-04 13:06:48.856895 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_INIT
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/hassan@a.b.c.d) State INIT
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:83
sofia/internal/hassan@a.b.c.d SOFIA INIT
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:119
(sofia/internal/hassan@a.b.c.d) State Change CS_INIT -> CS_ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:338
(sofia/internal/hassan@a.b.c.d) State INIT going to sleep
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_channel.c:1512
(sofia/internal/hassan@a.b.c.d) Callstate Change DOWN -> RINGING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/hassan@a.b.c.d) State ROUTING
2010-08-04 13:06:48.856895 [DEBUG] mod_sofia.c:142
sofia/internal/hassan@a.b.c.d SOFIA ROUTING
2010-08-04 13:06:48.856895 [DEBUG] switch_core_state_machine.c:77
sofia/internal/hassan@a.b.c.d Standard ROUTING
2010-08-04 13:06:48.856895 [INFO] mod_dialplan_xml.c:331 Processing
hassan->0111234567890 in context sky189
Dialplan: sofia/internal/hassan@a.b.c.d parsing [sky189->dial_sky189]
continue=false
Dialplan: sofia/internal/hassan@a.b.c.d Regex (PASS) [dial_sky189]
destination_number(0111234567890) =~ /^011(\d+)$/ break=on-false
Dialplan: sofia/internal/hassan@a.b.c.d Action
set(effective_caller_id_number=${outbound_caller_id_number})
Dialplan: sofia/internal/hassan@a.b.c.d Action
set(effective_caller_id_name=${outbound_caller_id_name})
Dialplan: sofia/internal/hassan@a.b.c.d Action
bridge(sofia/external/1234567890@sky189)
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:119
(sofia/internal/hassan@a.b.c.d) State Change CS_ROUTING -> CS_EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341
(sofia/internal/hassan@a.b.c.d) State ROUTING going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/hassan@a.b.c.d) State EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:235
sofia/internal/hassan@a.b.c.d SOFIA EXECUTE
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:157
sofia/internal/hassan@a.b.c.d Standard EXECUTE
EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_number=)
2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854
sofia/internal/hassan@a.b.c.d SET [effective_caller_id_number]=[UNDEF]
EXECUTE sofia/internal/hassan@a.b.c.d set(effective_caller_id_name=)
2010-08-04 13:06:48.858888 [DEBUG] mod_dptools.c:854
sofia/internal/hassan@a.b.c.d SET [effective_caller_id_name]=[UNDEF]
EXECUTE sofia/internal/hassan@a.b.c.dbridge(sofia/external/1234567890@sky189
)
2010-08-04 13:06:48.858888 [NOTICE] switch_channel.c:779 New Channel
sofia/external/1234567890@sky189 [cfbd2d4f-87fc-4c59-b320-2290a5a076b3]
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:3892
(sofia/external/1234567890@sky189) State Change CS_NEW -> CS_INIT
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1234567890@sky189) Running State Change CS_INIT
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338
(sofia/external/1234567890@sky189) State INIT
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:83
sofia/external/1234567890@sky189 SOFIA INIT
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:119
(sofia/external/1234567890@sky189) State Change CS_INIT -> CS_ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:338
(sofia/external/1234567890@sky189) State INIT going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1234567890@sky189) Running State Change CS_ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_channel.c:1512
(sofia/external/1234567890@sky189) Callstate Change DOWN -> RINGING
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341
(sofia/external/1234567890@sky189) State ROUTING
2010-08-04 13:06:48.858888 [DEBUG] mod_sofia.c:142
sofia/external/1234567890@sky189 SOFIA ROUTING
2010-08-04 13:06:48.858888 [DEBUG] switch_ivr_originate.c:66
(sofia/external/1234567890@sky189) State Change CS_ROUTING ->
CS_CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:341
(sofia/external/1234567890@sky189) State ROUTING going to sleep
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1234567890@sky189) Running State Change CS_CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360
(sofia/external/1234567890@sky189) State CONSUME_MEDIA
2010-08-04 13:06:48.858888 [DEBUG] switch_core_state_machine.c:360
(sofia/external/1234567890@sky189) State CONSUME_MEDIA going to sleep
2010-08-04 13:06:48.858888 [DEBUG] sofia.c:4318 Channel
sofia/external/1234567890@sky189 entering state [calling][0]
2010-08-04 13:06:48.861065 [DEBUG] sofia.c:4318 Channel
sofia/external/1234567890@sky189 entering state [terminated][503]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309
(sofia/external/1234567890@sky189) Callstate Change RINGING -> HANGUP
2010-08-04 13:06:48.861065 [NOTICE] sofia.c:4932 Hangup
sofia/external/1234567890@sky189 [CS_CONSUME_MEDIA]
[NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal
sofia/external/1234567890@sky189 [KILL]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1234567890@sky189) Running State Change CS_HANGUP
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535
(sofia/external/1234567890@sky189) State HANGUP
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447
sofia/external/1234567890@sky189 Overriding SIP cause 503 with 503 from the
other leg
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:453 Channel
sofia/external/1234567890@sky189 hanging up, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:46
sofia/external/1234567890@sky189 Standard HANGUP, cause:
NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535
(sofia/external/1234567890@sky189) State HANGUP going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:333
(sofia/external/1234567890@sky189) State Change CS_HANGUP -> CS_REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314
(sofia/external/1234567890@sky189) Running State Change CS_REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595
(sofia/external/1234567890@sky189) State REPORTING
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:53
sofia/external/1234567890@sky189 Standard REPORTING, cause:
NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:595
(sofia/external/1234567890@sky189) State REPORTING going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:327
(sofia/external/1234567890@sky189) State Change CS_REPORTING -> CS_DESTROY
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal
sofia/external/1234567890@sky189 [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_ivr_originate.c:3431 Originate
Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [INFO] mod_dptools.c:2393 Originate Failed.
 Cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2309
(sofia/internal/hassan@a.b.c.d) Callstate Change RINGING -> HANGUP
2010-08-04 13:06:48.861065 [NOTICE] mod_dptools.c:2456 Hangup
sofia/internal/hassan@a.b.c.d [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
2010-08-04 13:06:48.861065 [DEBUG] switch_channel.c:2325 Send signal
sofia/internal/hassan@a.b.c.d [KILL]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1905
sofia/internal/hassan@a.b.c.d skip receive message
[APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:348
(sofia/internal/hassan@a.b.c.d) State EXECUTE going to sleep
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_HANGUP
2010-08-04 13:06:48.861065 [DEBUG] switch_core_state_machine.c:535
(sofia/internal/hassan@a.b.c.d) State HANGUP
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:447
sofia/internal/hassan@a.b.c.d Overriding SIP cause 503 with 503 from the
other leg
2010-08-04 13:06:48.861065 [DEBUG] mod_sofia.c:453 Channel
sofia/internal/hassan@a.b.c.d hanging up, cause: NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.861065 [DEBUG] switch_core_session.c:1202 Session 11
(sofia/external/1234567890@sky189) Locked, Waiting on external entities
2010-08-04 13:06:48.861065 [NOTICE] switch_core_session.c:1220 Session 11
(sofia/external/1234567890@sky189) Ended
2010-08-04 13:06:48.862912 [NOTICE] switch_core_session.c:1222 Close Channel
sofia/external/1234567890@sky189 [CS_DESTROY]
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:427
(sofia/external/1234567890@sky189) Callstate Change HANGUP -> DOWN
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:430
(sofia/external/1234567890@sky189) Running State Change CS_DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440
(sofia/external/1234567890@sky189) State DESTROY
2010-08-04 13:06:48.862912 [DEBUG] mod_sofia.c:358
sofia/external/1234567890@sky189 SOFIA DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:60
sofia/external/1234567890@sky189 Standard DESTROY
2010-08-04 13:06:48.862912 [DEBUG] switch_core_state_machine.c:440
(sofia/external/1234567890@sky189) State DESTROY going to sleep
2010-08-04 13:06:48.864893 [DEBUG] mod_sofia.c:515 Responding to INVITE
with: 503
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:46
sofia/internal/hassan@a.b.c.d Standard HANGUP, cause:
NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:535
(sofia/internal/hassan@a.b.c.d) State HANGUP going to sleep
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:333
(sofia/internal/hassan@a.b.c.d) State Change CS_HANGUP -> CS_REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:314
(sofia/internal/hassan@a.b.c.d) Running State Change CS_REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:595
(sofia/internal/hassan@a.b.c.d) State REPORTING
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:53
sofia/internal/hassan@a.b.c.d Standard REPORTING, cause:
NORMAL_TEMPORARY_FAILURE
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:595
(sofia/internal/hassan@a.b.c.d) State REPORTING going to sleep
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:327
(sofia/internal/hassan@a.b.c.d) State Change CS_REPORTING -> CS_DESTROY
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1039 Send signal
sofia/internal/hassan@a.b.c.d [BREAK]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_session.c:1202 Session 10
(sofia/internal/hassan@a.b.c.d) Locked, Waiting on external entities
2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1220 Session 10
(sofia/internal/hassan@a.b.c.d) Ended
2010-08-04 13:06:48.864893 [NOTICE] switch_core_session.c:1222 Close Channel
sofia/internal/hassan@a.b.c.d [CS_DESTROY]
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:427
(sofia/internal/hassan@a.b.c.d) Callstate Change HANGUP -> DOWN
2010-08-04 13:06:48.864893 [DEBUG] switch_core_state_machine.c:430
(sofia/internal/hassan@a.b.c.d) Running State Change CS_DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/hassan@a.b.c.d) State DESTROY
2010-08-04 13:06:48.866921 [DEBUG] mod_sofia.c:358
sofia/internal/hassan@a.b.c.d SOFIA DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:60
sofia/internal/hassan@a.b.c.d Standard DESTROY
2010-08-04 13:06:48.866921 [DEBUG] switch_core_state_machine.c:440
(sofia/internal/hassan@a.b.c.d) State DESTROY going to sleep

[Freeswitch-users] Help on reading the log better

Nyamul Hassan