快速入门干货：SIP协议原理和FreeSWITCH调试日志消息对照分析

虽然知道FreeSWITCH很多年，但是实际学习这个软件的时间很少。
作为语音网关的硬件厂家，总是以解决客户实际问题为出发点，偶尔研究几分钟都是因为客户遇到对接的问题。为了赶进度，不可能去仔细研究freeswitch的设置，每次都是通过SIP协议原理，对比FreeSWITCH调试日志消息，互相参照，排查出可能的原因，再去倒推可能是哪方面的设置有问题。
所以，这里介绍的是我如何快速入门学习FreeSWITCH的干货，思路可能跟某些权威指南有所不同。
下面这个文档，您可能要对照上一篇《使用IAD电话交换机（语音网关）将电话外线对接到FreeSWITCH SIP服务器》一起看，更容易理解。

电话呼出的SIP协议和FreeSWITCH日志

SIP呼叫其实很简单，我们以电话呼出为例。这里呼出例子是根据上一篇文章来的，就是1000分机通过电话外线呼叫10086号码。SIP协议是这样的：

从FreeSWITCH日志上这样记录：

2024-03-06 19:05:33.172906 [NOTICE] switch_channel.c:1104 New Channel
sofia/internal/1000@192.168.3.13
[1ea401e7-6c7b-481f-8752-45742a320922] 2024-03-06 19:05:33.202908
[INFO] mod_dialplan_xml.c:637 Processing 1000 <1000>->010086 in
context default 2024-03-06 19:05:33.202908 [NOTICE]
switch_channel.c:1104 New Channel sofia/external/10086
[901fb9b0-35c9-4ea6-a4a4-3407e2937483] 2024-03-06 19:05:52.623019
[NOTICE] sofia.c:7156 Ring-Ready sofia/external/10086! 2024-03-06
19:05:52.633019 [NOTICE] mod_sofia.c:2272 Ring-Ready
sofia/internal/1000@192.168.3.13! 2024-03-06 19:05:52.633019 [NOTICE]
switch_ivr_originate.c:525 Ring Ready
sofia/internal/1000@192.168.3.13! 2024-03-06 19:05:54.123105 [NOTICE]
sofia.c:8144 Channel [sofia/external/10086] has been answered
2024-03-06 19:05:54.133105 [NOTICE] switch_ivr.c:779 Channel
[sofia/internal/1000@192.168.3.13] has been answered 2024-03-06
19:07:03.243058 [NOTICE] sofia.c:1012 Hangup
sofia/internal/1000@192.168.3.13 [CS_HIBERNATE] [NORMAL_CLEARING]
2024-03-06 19:07:03.243058 [NOTICE] switch_ivr_bridge.c:1289 Hangup
sofia/external/10086 [CS_HIBERNATE] [NORMAL_CLEARING] 2024-03-06
19:07:03.243058 [NOTICE] switch_core_session.c:1682 Session 2
(sofia/external/10086) Ended 2024-03-06 19:07:03.243058 [NOTICE]
switch_core_session.c:1686 Close Channel sofia/external/10086
[CS_DESTROY] 2024-03-06 19:07:03.243058 [NOTICE]
switch_core_session.c:1682 Session 1
(sofia/internal/1000@192.168.3.13) Ended 2024-03-06 19:07:03.243058
[NOTICE] switch_core_session.c:1686 Close Channel
sofia/internal/1000@192.168.3.13 [CS_DESTROY]

电话呼入的SIP协议和FreeSWITCH调试

从SIP协议是这样的，来看下：

对应的日志信息可以看看：

2024-03-06 19:11:12.323305 [NOTICE] switch_channel.c:1104 New Channel sofia/external/18719289062@192.168.3.13:5080 [f4d89a91-9ffb-4db9-b960-fb4429f4c465]
2024-03-06 19:11:12.373308 [INFO] mod_dialplan_xml.c:637 Processing 18719289062 <18719289062>->5551212 in context public
2024-03-06 19:11:12.373308 [NOTICE] switch_ivr.c:2172 Transfer sofia/external/18719289062@192.168.3.13:5080 to XML[1000@default]
2024-03-06 19:11:12.373308 [INFO] mod_dialplan_xml.c:637 Processing 18719289062 <18719289062>->1000 in context default
2024-03-06 19:11:12.373308 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *1 execute_extension::dx XML features
2024-03-06 19:11:12.383308 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *2 record_session::C:/Program Files/FreeSWITCH/recordings/18719289062.2024-03-06-19-11-12.wav
2024-03-06 19:11:12.383308 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *3 execute_extension::cf XML features
2024-03-06 19:11:12.383308 [INFO] switch_ivr_async.c:4171 Bound B-Leg: *4 execute_extension::att_xfer XML features
2024-03-06 19:11:12.383308 [INFO] switch_core_session.c:2648 Sending early media
2024-03-06 19:11:12.383308 [NOTICE] sofia_media.c:92 Pre-Answer sofia/external/18719289062@192.168.3.13:5080!
2024-03-06 19:11:12.433311 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@192.168.3.66:51142 [0d9f8f46-9394-4b60-978e-5f92bee992ca]
2024-03-06 19:11:12.433311 [NOTICE] switch_ivr_originate.c:2845 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2024-03-06 19:11:12.513316 [NOTICE] sofia.c:7156 Ring-Ready sofia/internal/1000@192.168.3.66:51142!
2024-03-06 19:11:24.342992 [NOTICE] sofia.c:8182 Channel [sofia/internal/1000@192.168.3.66:51142] has been answered
2024-03-06 19:11:24.362993 [NOTICE] switch_ivr_originate.c:3632 Channel [sofia/external/18719289062@192.168.3.13:5080] has been answered
2024-03-06 19:11:46.823278 [NOTICE] sofia.c:1012 Hangup sofia/internal/1000@192.168.3.66:51142 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2024-03-06 19:11:46.843279 [NOTICE] switch_ivr_bridge.c:1751 Hangup sofia/external/18719289062@192.168.3.13:5080 [CS_EXECUTE] [NORMAL_CLEARING]
2024-03-06 19:11:46.843279 [NOTICE] switch_core_session.c:1682 Session 4 (sofia/internal/1000@192.168.3.66:51142) Ended
2024-03-06 19:11:46.843279 [NOTICE] switch_core_session.c:1686 Close Channel sofia/internal/1000@192.168.3.66:51142 [CS_DESTROY]
2024-03-06 19:11:46.843279 [NOTICE] switch_core_session.c:1682 Session 3 (sofia/external/18719289062@192.168.3.13:5080) Ended
2024-03-06 19:11:46.843279 [NOTICE] switch_core_session.c:1686 Close Channel sofia/external/18719289062@192.168.3.13:5080 [CS_DESTROY]

所以怎么对比SIP消息和FreeSWITCH日志呢？

我们可以从FreeSWITCH Console里面根据这些关键词（比如Invite就是New Channel ， 180 Ringing就是对应Ring-Ready，200 OK就是对应就是对应has been answered）来看呼叫进展情况。
再配合dialplan信息，就可以理解到FreeSWITCH如何处理呼叫的了。 比如我们看下面这句日志：

2024-03-06 19:11:12.373308 [INFO] mod_dialplan_xml.c:637 Processing
18719289062 <18719289062>->5551212 in context public

mod_dialplan_xml 就是执行dialplan，对应的就是freeswitch/conf/dialplan下面的文件。根据主叫和被叫号码来匹配业务流程，5551212这个被叫号码（很多文档里会把这个叫做DID）有一个默认流程，文件名是00_inbound_did.xml ，我们把这个xml文件内容贴在下面：

<include>
  <extension name="public_did">
    <condition field="destination_number" expression="^(5551212)$">
      <!--
	  If you're hosting multiple domains you will want to set the
	  target_domain on these calls so they hit the proper domain after you
	  transfer the caller into the default context. 
	  
	  $${domain} is the default domain set from vars.xml but you can set it
	  to any domain you have setup in your user directory.

      --> 
      <action application="set" data="domain_name=$${domain}"/>
      <!-- This example maps the DID 5551212 to ring 1000 in the default context -->
      <action application="transfer" data="1000 XML default"/>
    </condition>
  </extension>
</include>

这个文档，有助于您更快捷的了解呼叫信令流程、电话业务处理流程。对于想深入了解SIP信令的同学来说，也可以把SIP debug打开（sofia loglevel all 9），就能看到详细的信令过程。