Core 2 Duo E8400 @3.00Ghz 2GB RAM
Sangoma A101
Git-1.7.11-preview20120710
FreeSWITCH Version 1.5.1b+git~20130417T225111Z~54d47599e9
wanpipe_6_0_46_0
libsng_isdn-7.6.2

mod_freetdm is loaded successfully (look at full log forwards).
But as a reaction on incoming calls FS console shows the next warning message:
> 2013-04-18 15:43:33.046875 [WARNING] ftmod_sangoma_isdn_stack_rcv.c:862 [SNGISDN Q931] s1: Internal: Unknown Event Code(5): Invalid PCB state(265).
Although the analyzer(linkbit) shows transmission of SETUP, RR, RR, 10sec delay, SETUP, RR, RR from PBX to FS(sangoma).

What it could be?
Grateful for any answers.


Full log:
freeswitch@telegraf-4a8f3c> load mod_freetdm
2013-04-18 15:03:35.765625 [INFO] mod_enum.c:872 ENUM Reloaded
2013-04-18 15:03:35.765625 [INFO] switch_time.c:1173 Timezone reloaded 530 definitions
2013-04-18 15:03:35.796875 [NOTICE] ftdm_sched.c:185 Launching main schedule thread
2013-04-18 15:03:35.796875 [NOTICE] ftdm_io.c:6330 Modules configured: 1
2013-04-18 15:03:35.812500 [INFO] ftdm_io.c:5499 Loading IO from C:/FS_GIT/Win32/Release/mod\ftmod_wanpipe.dll [wanpipe]

2013-04-18 15:03:35.812500 [ERR] ftdm_io.c:5445 Cannot open wanpipe.conf
2013-04-18 15:03:35.812500 [INFO] ftdm_io.c:860 Auto-loaded I/O module 'wanpipe'
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c1][1:1] Configured wanpipe device FD: 3620, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c2][1:2] Configured wanpipe device FD: 4936, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c3][1:3] Configured wanpipe device FD: 4948, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c4][1:4] Configured wanpipe device FD: 4956, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c5][1:5] Configured wanpipe device FD: 4964, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c6][1:6] Configured wanpipe device FD: 4972, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c7][1:7] Configured wanpipe device FD: 4980, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c8][1:8] Configured wanpipe device FD: 4988, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c9][1:9] Configured wanpipe device FD: 4996, DTMF: software, HW
EC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c10][1:10] Configured wanpipe device FD: 5004, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c11][1:11] Configured wanpipe device FD: 5012, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c12][1:12] Configured wanpipe device FD: 5020, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c13][1:13] Configured wanpipe device FD: 5028, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c14][1:14] Configured wanpipe device FD: 5036, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c15][1:15] Configured wanpipe device FD: 5044, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c16][1:17] Configured wanpipe device FD: 5052, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c17][1:18] Configured wanpipe device FD: 5060, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c18][1:19] Configured wanpipe device FD: 5068, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c19][1:20] Configured wanpipe device FD: 5076, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c20][1:21] Configured wanpipe device FD: 5084, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c21][1:22] Configured wanpipe device FD: 5092, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c22][1:23] Configured wanpipe device FD: 5100, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c23][1:24] Configured wanpipe device FD: 5108, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c24][1:25] Configured wanpipe device FD: 5116, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c25][1:26] Configured wanpipe device FD: 5124, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c26][1:27] Configured wanpipe device FD: 5132, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c27][1:28] Configured wanpipe device FD: 5140, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c28][1:29] Configured wanpipe device FD: 5148, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c29][1:30] Configured wanpipe device FD: 5156, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c30][1:31] Configured wanpipe device FD: 5164, DTMF: software,
HWEC: unavailable, HWEC_IDLE: enabled
2013-04-18 15:03:35.812500 [INFO] ftmod_wanpipe.c:420 [s1c31][1:16] Configured wanpipe device FD: 5168, DTMF: none, HWEC
: none, HWEC_IDLE: none
2013-04-18 15:03:35.843750 [INFO] ftdm_io.c:5421 Configured 31 channel(s)
2013-04-18 15:03:35.937500 [INFO] ftdm_io.c:5499 Loading IO from C:/FS_GIT/Win32/Release/mod\ftmod_sangoma_isdn.dll [san
goma_isdn]
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn.c:1338 Loading ftmod_sangoma_isdn...
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1102 sng_isdn->

===========================================
=       Sangoma FreeTDM ISDN Library      =
=          Version:7.6.2               =
===========================================


2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully registered Stack Manager
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully started a task for Stack Ma
nager
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully attached Stack Manager to i
t's task
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully registered Call Control
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully started a task for Call Con
trol
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully attached Call Control to it
's task
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully registered Q.930/Q.931
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully started a task for Q.930/Q.
931
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully attached Q.930/Q.931 to it'
s task
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully registered LAPD
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully started a task for LAPD
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully attached LAPD to it's task
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully registered Physical Layer
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully started a task for Physical
 Layer
2013-04-18 15:03:35.937500 [INFO] ftmod_sangoma_isdn_stack_rcv.c:1098 sng_isdn->Successfully attached Physical Layer to
it's task
2013-04-18 15:03:36.437500 [INFO] ftmod_sangoma_isdn_stack_cfg.c:89 General stack configuration done
2013-04-18 15:03:36.437500 [INFO] ftdm_io.c:5511 Loading SIG from C:/FS_GIT/Win32/Release/mod\ftmod_sangoma_isdn.dll
2013-04-18 15:03:36.437500 [INFO] ftdm_io.c:5735 auto-loaded 'sangoma_isdn'
2013-04-18 15:03:36.437500 [INFO] ftmod_sangoma_isdn.c:1184 Configuring ftmod_sangoma_isdn span = wp1
2013-04-18 15:03:36.453125 [INFO] ftmod_sangoma_isdn_stack_cfg.c:159 wp1:stack configuration done
2013-04-18 15:03:36.453125 [INFO] ftmod_sangoma_isdn.c:1331 Finished configuring ftmod_sangoma_isdn span = wp1
2013-04-18 15:03:36.453125 [INFO] ftmod_sangoma_isdn.c:1089 Starting span wp1:1.
2013-04-18 15:03:37.265625 [INFO] ftmod_sangoma_isdn_stack_cntrl.c:88 wp1:Stack activated
2013-04-18 15:03:37.265625 [INFO] ftmod_sangoma_isdn.c:447 ftmod_sangoma_isdn monitor thread for span=1 started.
2013-04-18 15:03:37.265625 [CONSOLE] switch_loadable_module.c:1350 Successfully Loaded [mod_freetdm]
2013-04-18 15:03:37.265625 [INFO] ftmod_sangoma_isdn_stack_rcv.c:825 [SNGISDN Q931] s1: Interface: UP(260): Dchan(285)
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:146 Adding Endpoint 'freetdm'
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:254 Adding Application 'disable_ec'
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:254 Adding Application 'disable_dtmf'
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:254 Adding Application 'enable_dtmf'
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:298 Adding API Function 'ftdm'
2013-04-18 15:03:37.265625 [NOTICE] switch_loadable_module.c:298 Adding API Function 'ftdm_usage'

+OK Reloading XML
+OK

2013-04-18 15:03:37.281250 [INFO] ftmod_sangoma_isdn_stack_rcv.c:675 Received RESTART CFM (dChan:1 ces:0 type:0)
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:1 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:2 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:3 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:4 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:5 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:6 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:7 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:8 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:9 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:10 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:11 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:12 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:13 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:14 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:15 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:16 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:17 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:18 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:19 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:20 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:21 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:22 signalling changed to :UP
2013-04-18 15:03:37.281250 [INFO] mod_freetdm.c:2733 1:23 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:24 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:25 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:26 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:27 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:28 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:29 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:30 signalling changed to :UP
2013-04-18 15:03:37.296875 [INFO] mod_freetdm.c:2733 1:31 signalling changed to :UP

freeswitch@telegraf-4a8f3c>

freeswitch@telegraf-4a8f3c>

freeswitch@telegraf-4a8f3c> ftdm list

+OK
span: 1 (wp1)
type: Sangoma (ISDN)
physical_status: ok
signaling_status: UP
chan_count: 31
dialplan: XML
context: default
dial_regex:
fail_dial_regex:
hold_music:
analog_options: none


freeswitch@telegraf-4a8f3c> ftdm sangoma_isdn trace q931 wp1
2013-04-18 15:04:38.484375 [INFO] ftmod_sangoma_isdn_stack_cntrl.c:271 s1 Enabling q931 trace

Command executed OK


freeswitch@telegraf-4a8f3c> ftdm sangoma_isdn trace q921 wp1
2013-04-18 15:04:42.015625 [INFO] ftmod_sangoma_isdn_stack_cntrl.c:261 wp1:Enabling q921 trace

Command executed OK


freeswitch@telegraf-4a8f3c> 2013-04-18 15:06:44.843750 [WARNING] ftmod_sangoma_isdn_stack_rcv.c:862 [SNGISDN Q931] s1: I
nternal: Unknown Event Code(5): Invalid PCB state(265)
2013-04-18 15:06:54.843750 [WARNING] ftmod_sangoma_isdn_stack_rcv.c:862 [SNGISDN Q931] s1: Internal: Unknown Event Code(
5): Invalid PCB state(265)
2013-04-18 15:07:30.375000 [WARNING] ftmod_sangoma_isdn_stack_rcv.c:862 [SNGISDN Q931] s1: Internal: Unknown Event Code(
5): Invalid PCB state(265)
2013-04-18 15:07:40.359375 [WARNING] ftmod_sangoma_isdn_stack_rcv.c:862 [SNGISDN Q931] s1: Internal: Unknown Event Code(
5): Invalid PCB state(265)
...
...
...

With best regards, Shumaev DA, KBR Ltd.