[Asterisk-Users] how to debug frame slips?

Tue Dec 28 00:24:32 MST 2004

Mike, thanks so much.. here are the results - unfortunately, not even a new
build on a new system is solving this issue.

* See my notes to the tests below.  I ended up trying 3 computers, the last
being a Dell 1600 server with a fresh install following the AMP instructions
at http://amp.coalescentsystems.ca/docs/AMP_Installation_Guide_v1.1.pdf.

>Joe Presto wrote:
>> Hi, Im running into issues receiving faxes which, from what I have 
>> read, may be caused by frame slips.  While I can find many posts saying 
>> to investigate it, I cant find any that describe **how** to debug the 
>> problem. Tried searching this list as well to no avail.
>> 

>Joe Hi,
>
>Boot the Linux Rescue disk and run memtest86.

* tested OK

>Boot Linux but don't go into XWindows.

* no xwin on system

>If you're running software RAID, 'cat /proc/mdstat'.  If it's syncing a 
>drive then wait till it's done.

* no raid

>Check 'cat /proc/interrupts' for modules sharing the same interrupt 
>vector.  Even an unused USB module, when shared with a Digium module, 
>will cause havoc.  If you can, you may 'modprobe -r <name>' the shared 
>module.  If you can't, try moving the Digium card to different PCI slots 
>ion order to find an unshared interrupt vector.  You can also try 
>assigning irq numbers in BIOS.

* no interrupts being shared

>Check 'vmstat 1'.  With a "quiet" system you should see mostly 100% idle 
>time.  How many interrupts are you seeing per one second interval?  It 
>should be +/- 1000 for the system timer and +/- 1000 for each Digium card.>

* confirmed.. about 1100 interrupts per sec

>If you're seeing a lot of activity on vmstat then turn-off unneeded 
>services.

>Pick-up the handset and listen carefully to the dial tone.  It should be 
>pure MF tones.  If you hear any clicks, pops, or strangeness you know 
>you have a problem.  Listen to both the TDM card dialtone as well as the 
>channel bank dialtone (if you have one).

* sounds fine.  Gsm audio plays fine.  I'm seeing some issues with mp3 music
on hold, but I have a feeling it is my files.

>If you have two FXS lines with fax machines, fax a document directly 
>from one to the other.  Don't even start with spandsp until this works 
>c>onsistently.  If you have both TDM and T-1 then fax TDM->TDM, TDM->CB, 
>CB->TDM, and CB->CB.

* I don't have this, but I do have one FXS and one FXO, so I was able to
have an external fax go through * to a fax machine.  Worked perfectly.

>After you RxFax a document, open the received .tiff file a tiff viewer 
>or your browser (I use Mozilla).  Verify the file contents.

>Use TxFax to send the file back to the fax machine.  Did it print
correctly?

>When fax->fax works correctly, try spandsp.
>
>If you still have problems:
>
>If you're on a channel bank (or PSTN circuit) then look at your T-1 
>timing. In the US you should have something like 'span=1,1,0,esf,b8zs' 
>in zaptel.conf where the T-1 card is taking its timing from the received 
>data stream.  The channel bank should be configured to generate its own 
>timing.
>
* t400p not channel bank

>If you have IDE drives, try 'hdparm /dev/hdx'.  If 32-bit support is 0 
>then try 'hdparm -c1 /dev/hdx' and 'hdparm -c3 /dev/hdx'.  If using_dma 
>is 0 then try 'hdparm -d1 /dev/hdx'.  I configured a RAMDISK to 
>eliminate the possibility of disk I/O interfering with spandsp.

* ran with scsi - n/a

>Try 'lspci -v' and look at the latency timer for your Digium card(s). 
>You can set it higher with 'setpci -v -s xx:yy.0 LATENCY=TIMER=ff' (xx 
>is the bus number and yy is the slot).

* tried, with no effect

>Look at the vmstat output and check for system (not user) spikes every 
>three seconds.  If you have spikes then 'modprobe -r wcfxs'--if no more 
>spikes then get a T-1 card and channel bank and try it there.

* here's sample output: 
procs                      memory      swap          io     system
cpu
 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy wa
id
4  0      0  56020  12224 137968    0    0     0     0 1114   173  0  0  0
100
 0  0      0  56020  12224 137968    0    0     0     0 1113   181  0  0  0
100
 0  0      0  56020  12224 137968    0    0     0     0 1115   175  0  0  0
100
 0  0      0  56020  12232 137968    0    0     0    20 1117   184  0  0  2
98
 0  0      0  56020  12232 137968    0    0     0     0 1114   172  0  0  0
100
 0  0      0  56020  12232 137968    0    0     0     0 1113   170  0  0  0
100
 0  0      0  56020  12232 137968    0    0     0     0 1115   173  0  0  0
100
 0  0      0  56020  12232 137968    0    0     0     0 1113   175  0  0  0
100
 0  0      0  56020  12240 137968    0    0     0    16 1117   179  0  0  2
98
 1  0      0  56020  12240 137968    0    0     0     0 1113   174  0  0  0
100
 4  0      0  56020  12240 137968    0    0     0     0 1115   170  0  0  0
100
14  0      0  56020  12240 137968    0    0     0     0 1114   164  0  0  0
100
 0  0      0  56020  12240 137968    0    0     0     0 1114   175  0  0  0
100
 0  0      0  56020  12248 137968    0    0     0    20 1116   180  0  0  1
99
 0  0      0  56020  12248 137968    0    0     0     0 1114   170  0  0  0
100

there appears to be a tiny spike every 5 secs or so.  I can't stop wcfxs
without stopping asterisk.  The spikes stop after stopping asterisk/AMP.

Following is a log of my fax session.. perhaps there is something I'm
missing?

Dec 28 01:46:08 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:46:18 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:46:18 VERBOSE[1046]:     -- Starting simple switch on 'Zap/4-1'
Dec 28 01:46:24 NOTICE[1046]: Got event 2 (Ring/Answered)...
Dec 28 01:46:24 VERBOSE[1046]:     -- Executing
ESC[1;36;40mAnswerESC[0;37;40m(
"ESC[1;35;40mZap/4-1ESC[0;37;40m", "ESC[1;35;40mESC[0;37;40m") in new stack
Dec 28 01:46:24 DEBUG[1046]: Took Zap/4-1 off hook
Dec 28 01:46:24 DEBUG[1046]: Enabled echo cancellation on channel 4
Dec 28 01:46:24 DEBUG[1046]: Engaged echo training on channel 4
Dec 28 01:46:24 VERBOSE[1046]:     -- Executing
ESC[1;36;40mBackGroundESC[0;37;
40m("ESC[1;35;40mZap/4-1ESC[0;37;40m",
"ESC[1;35;40mdg-welcome-to-dgESC[0;37;40
m") in new stack
Dec 28 01:46:24 DEBUG[1046]: Scheduling timer at 160 sample intervals
Dec 28 01:46:24 VERBOSE[1046]:     -- Playing 'dg-welcome-to-dg' (language
'en'
)
Dec 28 01:46:27 DEBUG[1046]: DTMF digit: f on Zap/4-1
Dec 28 01:46:27 VERBOSE[1046]:     -- Redirecting Zap/4-1 to fax extension
Dec 28 01:46:27 DEBUG[1046]: Scheduling timer at 0 sample intervals
Dec 28 01:46:27 VERBOSE[1046]:   == Spawn extension (from-pstn, fax, 0)
exited 
non-zero on 'Zap/4-1'
Dec 28 01:46:27 VERBOSE[1046]:     -- Executing
ESC[1;36;40mRxFAXESC[0;37;40m("
ESC[1;35;40mZap/4-1ESC[0;37;40m",
"ESC[1;35;40m/var/spool/asterisk/fax/123.tif
ESC[0;37;40m") in new stack
Dec 28 01:46:28 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:46:38 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:46:46 DEBUG[1046]:
==================================================
============================
Dec 28 01:46:46 DEBUG[1046]: Pages transferred:  1
Dec 28 01:46:46 DEBUG[1046]: Image size:         1728 x 109
Dec 28 01:46:46 DEBUG[1046]: Image resolution    7700 x 3850
Dec 28 01:46:46 DEBUG[1046]: Transfer Rate:      9600
Dec 28 01:46:46 DEBUG[1046]: Bad rows            12
Dec 28 01:46:46 DEBUG[1046]: Longest bad row run 5
Dec 28 01:46:46 DEBUG[1046]: Compression type    2
Dec 28 01:46:46 DEBUG[1046]: Image size (bytes)  0
Dec 28 01:46:46 DEBUG[1046]:
==================================================
============================
Dec 28 01:46:48 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:46:58 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:47:05 DEBUG[1046]:
==================================================
============================
Dec 28 01:47:05 DEBUG[1046]: Pages transferred:  2
Dec 28 01:47:05 DEBUG[1046]: Image size:         1728 x 138
Dec 28 01:47:05 DEBUG[1046]: Image resolution    7700 x 3850
Dec 28 01:47:05 DEBUG[1046]: Transfer Rate:      9600
Dec 28 01:47:05 DEBUG[1046]: Bad rows            19
Dec 28 01:47:05 DEBUG[1046]: Longest bad row run 8
Dec 28 01:47:05 DEBUG[1046]: Compression type    2
Dec 28 01:47:05 DEBUG[1046]: Image size (bytes)  0
Dec 28 01:47:05 DEBUG[1046]:
==================================================
============================
Dec 28 01:47:08 DEBUG[1046]: Manager received command 'Command'
Dec 28 01:47:08 DEBUG[1046]:
==================================================
============================
Dec 28 01:47:08 DEBUG[1046]: Fax successfully received.
Dec 28 01:47:08 DEBUG[1046]: Remote station id: Sent via MaxEmail   
Dec 28 01:47:08 DEBUG[1046]: Local station id:  
Dec 28 01:47:08 DEBUG[1046]: Pages transferred: 2
Dec 28 01:47:08 DEBUG[1046]: Image resolution:  7700 x 3850
Dec 28 01:47:08 DEBUG[1046]: Transfer Rate:     9600
Dec 28 01:47:08 DEBUG[1046]:
==================================================
============================
Dec 28 01:47:09 DEBUG[1046]: Exception on 21, channel 4
Dec 28 01:47:09 DEBUG[1046]: Got event On hook(1) on channel 4 (index 0)
Dec 28 01:47:09 DEBUG[1046]: disabled echo cancellation on channel 4
Dec 28 01:47:09 DEBUG[1046]: cdr_mysql: inserting a CDR record.
Dec 28 01:47:09 DEBUG[1046]: cdr_mysql: SQL command as follows:  INSERT INTO
cd
r
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration
,
billsec,disposition,amaflags,accountcode) VALUES ('2004-12-28
01:46:24','','','
s','from-pstn',
'Zap/4-1','','RxFAX','/var/spool/asterisk/fax/123.tif',45,45,'A
NSWERED',3,'')
Dec 28 01:47:09 DEBUG[1046]: Hangup: channel: 4 index = 0, normal = 21,
callwai
t = -1, thirdcall = -1
Dec 28 01:47:09 DEBUG[1046]: disabled echo cancellation on channel 4
Dec 28 01:47:09 DEBUG[1046]: Set option TDD MODE, value: OFF(0) on Zap/4-1
Dec 28 01:47:09 DEBUG[1046]: Updated conferencing on 4, with 0 conference
users
Dec 28 01:47:09 VERBOSE[1046]:     -- Hungup 'Zap/4-1'

Thanks again - joe