Thread: [iaxmodem-users] Adjusting skew
Brought to you by:
faxguy
From: Joseph J. <jja...@an...> - 2016-07-28 20:10:50
|
Hey all, Code base: iaxmodem -V 1.2.0 spandsp-0.0.5-snapshot-20080725 libiax2-0.2.3-SVN-20071223+ Asterisk 13.5.0 Iaxmodem + hylafax is installed on the asterisk server. Iax peer is configured as localhost. We I send to one of the sip gateways, even one located on the same core Ethernet switches I am still getting the majority of calls failing to carrier detected and getting nothing but "adjusting skew" starts at adjusting skew 10 all the way up to 4060. Is there any other debugging I can do to pinpoint the root cause of this issue? I've tried multiple versions of asterisk even going back to 1.4.X. Any pointers would be super helpful. Thanks! Joseph |
From: Lee H. <fa...@ho...> - 2016-07-28 21:01:10
|
On 07/28/2016 01:10 PM, Joseph Jackson wrote: > Code base: > > iaxmodem -V > > 1.2.0 > > spandsp-0.0.5-snapshot-20080725 > > libiax2-0.2.3-SVN-20071223+ > > Asterisk 13.5.0 > > Iaxmodem + hylafax is installed on the asterisk server. Iax peer is > configured as localhost. We I send to one of the sip gateways, even > one located on the same core Ethernet switches I am still getting the > majority of calls failing to carrier detected and getting nothing but > "adjusting skew" starts at adjusting skew 10 all the way up to 4060. > > Is there any other debugging I can do to pinpoint the root cause of > this issue? I've tried multiple versions of asterisk even going back > to 1.4.X. > > Any pointers would be super helpful. > In your iaxmodem config file (in /etc/iaxmodem/...) you can put "iax2debug" (on a line by itself), and then iaxmodem will produce libiax2 debugging information on stdout. That said... "Skew" is how iaxmodem tries to sense and adjust to the clock of the media channel. iaxmodem only has access to the system clock, and that could be slower or faster than the clock on the other end of the call. Because fax signals are sensitive to duration (time) and because jitter can be introduced by a disparity in the clocks on the ends of a call, iaxmodem attempts to adjust its own perception of time based on the frequency of audio packets received from Asterisk. In other words, iaxmodem counts the number of audio packets received and attempts to send the same number of audio packets by altering its perception of time through a "skew" value. On an average call the skew does adjust a bit at the outset of a call. After a few seconds, however, it should stabilize and maybe fluctuate between two close values. If iaxmodem is not receiving any audio packets from Asterisk, then you will see the skew grow until the call is disconnected. In such a situation iaxmodem would be trying to slow down its perception of time to reduce the number of audio packets it is sending... until it, too, would not be sending audio packets at all (because it is not receiving any). That is probably what is happening in your case. So, it's probably a case of iaxmodem not getting any audio packets from Asterisk.... which probably means that some kind of media path switch occurred (like a switch to T.38) or simply a firewalling issue or something. You're likely to get more-useful information from the Asterisk CLI. I'm curious as to why you're using iaxmodem-1.2.0, though. Does v1.3.0 not work for you? Thanks, Lee. |
From: Joseph J. <jja...@an...> - 2016-07-28 21:27:25
|
Hi Lee, Thanks for the reply You are correct wonder why. I was changing up versions of iaxmodem to see if the issue was version related. Running 1.3.0 now. I've enabled the debugging. I read that about skew and I would agree if I was trying to send this over a poor quality internet circuit. The iaxmomdem instance and the asterisk install are all on the same physical host. The SIP gateway the asterisk box sends too plugged into the same Ethernet switch. The termination trunk group I'm sending the call out of is an ss7 trunk so I don't think its media issues but I'm open to anything. We are a voip wholesale provider and I'm using this to test fax termination/support tickets so we try to maintain a high quality / low latency low jitter network. BTW I did a pcap of the call and I'm able to hear both legs trying to negotiate the fax setup. I'll get the debugging messages together. Thanks for the assistance! Joseph From: Lee Howard [mailto:fa...@ho...] Sent: Thursday, July 28, 2016 4:01 PM To: Joseph Jackson Cc: iax...@li... Subject: Re: [iaxmodem-users] Adjusting skew On 07/28/2016 01:10 PM, Joseph Jackson wrote: Code base: iaxmodem -V 1.2.0 spandsp-0.0.5-snapshot-20080725 libiax2-0.2.3-SVN-20071223+ Asterisk 13.5.0 Iaxmodem + hylafax is installed on the asterisk server. Iax peer is configured as localhost. We I send to one of the sip gateways, even one located on the same core Ethernet switches I am still getting the majority of calls failing to carrier detected and getting nothing but "adjusting skew" starts at adjusting skew 10 all the way up to 4060. Is there any other debugging I can do to pinpoint the root cause of this issue? I've tried multiple versions of asterisk even going back to 1.4.X. Any pointers would be super helpful. In your iaxmodem config file (in /etc/iaxmodem/...) you can put "iax2debug" (on a line by itself), and then iaxmodem will produce libiax2 debugging information on stdout. That said... "Skew" is how iaxmodem tries to sense and adjust to the clock of the media channel. iaxmodem only has access to the system clock, and that could be slower or faster than the clock on the other end of the call. Because fax signals are sensitive to duration (time) and because jitter can be introduced by a disparity in the clocks on the ends of a call, iaxmodem attempts to adjust its own perception of time based on the frequency of audio packets received from Asterisk. In other words, iaxmodem counts the number of audio packets received and attempts to send the same number of audio packets by altering its perception of time through a "skew" value. On an average call the skew does adjust a bit at the outset of a call. After a few seconds, however, it should stabilize and maybe fluctuate between two close values. If iaxmodem is not receiving any audio packets from Asterisk, then you will see the skew grow until the call is disconnected. In such a situation iaxmodem would be trying to slow down its perception of time to reduce the number of audio packets it is sending... until it, too, would not be sending audio packets at all (because it is not receiving any). That is probably what is happening in your case. So, it's probably a case of iaxmodem not getting any audio packets from Asterisk.... which probably means that some kind of media path switch occurred (like a switch to T.38) or simply a firewalling issue or something. You're likely to get more-useful information from the Asterisk CLI. I'm curious as to why you're using iaxmodem-1.2.0, though. Does v1.3.0 not work for you? Thanks, Lee. |
From: Lee H. <fa...@ho...> - 2016-07-28 23:52:31
|
On 07/28/2016 02:27 PM, Joseph Jackson wrote: > I did a pcap of the call and I'm able to hear both legs trying to > negotiate the fax setup. Then it would seem that the audio is getting through. Assuming that you're using HylaFAX, what does the HylaFAX session log (/var/spool/hylafax/log/...) show? Thanks, Lee. |
From: Joseph J. <jja...@an...> - 2016-07-29 04:21:02
|
Evening Lee, Here is the logging from hylafax for two calls. First is a failure that I then had hylafax retry automatically after 4 minutes. The second attempt was successful. No changes to routing or anything were made between these two attempts. ****FAILURE**** Jul 29 04:11:58.86: [15934]: SESSION BEGIN 000000099 XXXXXXXXXXXXX Jul 29 04:11:58.86: [15934]: HylaFAX (tm) Version 5.5.8 Jul 29 04:11:58.86: [15934]: SEND FAX: JOB 67 DEST XXXXXXXXXXXXX COMMID 000000099 DEVICE '/dev/ttyIAX0' FROM 'root <root@localhost>' USER admin Jul 29 04:11:58.86: [15934]: STATE CHANGE: RUNNING -> SENDING Jul 29 04:11:58.86: [15934]: <-- [12:AT+FCLASS=1\r] Jul 29 04:11:58.86: [15934]: --> [2:OK] Jul 29 04:11:58.86: [15934]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled Jul 29 04:11:58.89: [15934]: DIAL XXXXXXXXXXXXX Jul 29 04:11:58.89: [15934]: <-- [18:ATDTXXXXXXXXXXXXX\r] Jul 29 04:12:57.74: [15934]: --> [10:NO CARRIER] Jul 29 04:12:57.74: [15934]: SEND FAILED: JOB 67 DEST XXXXXXXXXXXXX ERR No carrier detected {E002} Jul 29 04:12:58.74: [15934]: <-- [5:ATH0\r] Jul 29 04:12:58.74: [15934]: --> [2:OK] Jul 29 04:12:58.74: [15934]: MODEM set DTR OFF Jul 29 04:12:58.74: [15934]: MODEM set baud rate: 0 baud (flow control unchanged) Jul 29 04:12:58.74: [15934]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5) Jul 29 04:12:58.74: [15934]: SESSION END ****SUCCESSFUL**** Jul 29 04:18:00.94: [16256]: SESSION BEGIN 000000100 XXXXXXXXXXXXX Jul 29 04:18:00.94: [16256]: HylaFAX (tm) Version 5.5.8 Jul 29 04:18:00.94: [16256]: SEND FAX: JOB 67 DEST XXXXXXXXXXXXX COMMID 000000100 DEVICE '/dev/ttyIAX0' FROM 'root <root@localhost>' USER admin Jul 29 04:18:00.94: [16256]: STATE CHANGE: RUNNING -> SENDING Jul 29 04:18:00.94: [16256]: <-- [12:AT+FCLASS=1\r] Jul 29 04:18:00.95: [16256]: --> [2:OK] Jul 29 04:18:00.95: [16256]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled Jul 29 04:18:00.98: [16256]: DIAL XXXXXXXXXXXXX Jul 29 04:18:00.98: [16256]: <-- [18:ATDTXXXXXXXXXXXXX\r] Jul 29 04:18:12.51: [16256]: --> [7:CONNECT] Jul 29 04:18:14.13: [16256]: --> HDLC<25:FF C0 02 8C 0C EC AC 8C 4C CC 0C 8C CC 04 04 04 04 04 04 04 04 04 04 E6 15> Jul 29 04:18:14.13: [16256]: --> [2:OK] Jul 29 04:18:14.13: [16256]: REMOTE CSI "3103215701" Jul 29 04:18:14.13: [16256]: <-- [9:AT+FRH=3\r] Jul 29 04:18:14.69: [16256]: --> [7:CONNECT] Jul 29 04:18:14.69: [16256]: --> HDLC<19:FF C8 01 04 77 1F 23 01 F9 01 01 01 05 01 01 01 00 AE 10> Jul 29 04:18:14.71: [16256]: --> [2:OK] Jul 29 04:18:14.71: [16256]: REMOTE best rate 33600 bit/s Jul 29 04:18:14.71: [16256]: REMOTE max A4 page width (215 mm) Jul 29 04:18:14.71: [16256]: REMOTE max unlimited page length Jul 29 04:18:14.71: [16256]: REMOTE best vres R16 x 15.4 line/mm Jul 29 04:18:14.71: [16256]: REMOTE format support: MH, MR, MMR, JBIG Jul 29 04:18:14.71: [16256]: REMOTE supports T.30 Annex A, 256-byte ECM Jul 29 04:18:14.71: [16256]: REMOTE best 0 ms/scanline Jul 29 04:18:14.71: [16256]: USE 14400 bit/s Jul 29 04:18:14.71: [16256]: USE error correction mode Jul 29 04:18:14.71: [16256]: SEND file "docq/doc83.ps;1c00" Jul 29 04:18:14.71: [16256]: USE A4 page width (215 mm) Jul 29 04:18:14.71: [16256]: USE unlimited page length Jul 29 04:18:14.71: [16256]: USE 3.85 line/mm Jul 29 04:18:14.71: [16256]: USE JBIG Jul 29 04:18:14.71: [16256]: USE 0 ms/scanline Jul 29 04:18:14.71: [16256]: SEND training at v.17 14400 bit/s Jul 29 04:18:14.71: [16256]: <-- [9:AT+FRS=7\r] Jul 29 04:18:14.83: [16256]: --> [2:OK] Jul 29 04:18:14.83: [16256]: <-- [9:AT+FTH=3\r] Jul 29 04:18:14.85: [16256]: --> [7:CONNECT] Jul 29 04:18:14.85: [16256]: <-- HDLC<23:FF C0 C2 0E AE 2E A6 CA E6 76 96 16 2E F6 72 04 04 04 04 04 04 04 04> Jul 29 04:18:14.85: [16256]: <-- data [23] Jul 29 04:18:14.85: [16256]: <-- data [2] Jul 29 04:18:16.39: [16256]: --> [7:CONNECT] Jul 29 04:18:16.39: [16256]: <-- HDLC<13:FF C8 C1 00 44 1F 21 01 01 01 01 01 04> Jul 29 04:18:16.39: [16256]: <-- data [13] Jul 29 04:18:16.39: [16256]: <-- data [2] Jul 29 04:18:16.95: [16256]: --> [2:OK] Jul 29 04:18:16.95: [16256]: <-- [9:AT+FTS=7\r] Jul 29 04:18:17.05: [16256]: --> [2:OK] Jul 29 04:18:17.05: [16256]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled Jul 29 04:18:17.05: [16256]: <-- [11:AT+FTM=145\r] Jul 29 04:18:17.07: [16256]: --> [7:CONNECT] Jul 29 04:18:17.07: [16256]: DELAY 400 ms Jul 29 04:18:17.47: [16256]: <-- data [1024] Jul 29 04:18:17.47: [16256]: <-- data [1024] Jul 29 04:18:17.47: [16256]: <-- data [652] Jul 29 04:18:17.47: [16256]: <-- data [2] Jul 29 04:18:20.03: [16256]: --> [2:OK] Jul 29 04:18:20.03: [16256]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled Jul 29 04:18:20.03: [16256]: <-- [9:AT+FRH=3\r] Jul 29 04:18:20.85: [16256]: --> [7:CONNECT] Jul 29 04:18:21.93: [16256]: --> HDLC<5:FF C8 21 57 BE> Jul 29 04:18:21.95: [16256]: --> [2:OK] Jul 29 04:18:21.95: [16256]: TRAINING succeeded Jul 29 04:18:21.95: [16256]: SEND begin page Jul 29 04:18:21.95: [16256]: Reading MH-compressed image file Jul 29 04:18:21.98: [16256]: SEND send frame number 0 Jul 29 04:18:21.98: [16256]: SEND send frame number 1 Jul 29 04:18:21.98: [16256]: SEND send frame number 2 Jul 29 04:18:21.98: [16256]: SEND send frame number 3 Jul 29 04:18:21.98: [16256]: SEND send frame number 4 Jul 29 04:18:21.98: [16256]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled Jul 29 04:18:21.98: [16256]: <-- [9:AT+FRS=7\r] Jul 29 04:18:22.07: [16256]: --> [2:OK] Jul 29 04:18:22.07: [16256]: <-- [11:AT+FTM=146\r] Jul 29 04:18:22.09: [16256]: --> [7:CONNECT] Jul 29 04:18:22.09: [16256]: DELAY 400 ms Jul 29 04:18:22.49: [16256]: <-- data [1027] Jul 29 04:18:22.49: [16256]: <-- data [695] Jul 29 04:18:22.49: [16256]: <-- data [2] Jul 29 04:18:23.53: [16256]: --> [2:OK] Jul 29 04:18:23.53: [16256]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled Jul 29 04:18:23.53: [16256]: <-- [9:AT+FTS=9\r] Jul 29 04:18:23.65: [16256]: --> [2:OK] Jul 29 04:18:23.65: [16256]: <-- [9:AT+FTH=3\r] Jul 29 04:18:23.67: [16256]: --> [7:CONNECT] Jul 29 04:18:23.67: [16256]: <-- HDLC<7:FF C8 FD F4 00 00 20> Jul 29 04:18:23.67: [16256]: <-- data [7] Jul 29 04:18:23.67: [16256]: <-- data [2] Jul 29 04:18:24.85: [16256]: --> [2:OK] Jul 29 04:18:24.85: [16256]: SEND send PPS (partial page signal) Jul 29 04:18:24.85: [16256]: SEND send EOP (no more pages or documents) Jul 29 04:18:24.85: [16256]: <-- [9:AT+FRH=3\r] Jul 29 04:18:25.97: [16256]: --> [7:CONNECT] Jul 29 04:18:27.05: [16256]: --> HDLC<5:FF C8 31 45 8F> Jul 29 04:18:27.07: [16256]: --> [2:OK] Jul 29 04:18:27.07: [16256]: SEND recv MCF (message confirmation) Jul 29 04:18:27.07: [16256]: <-- [9:AT+FRS=7\r] Jul 29 04:18:27.19: [16256]: --> [2:OK] Jul 29 04:18:27.19: [16256]: SEND end page Jul 29 04:18:27.19: [16256]: SEND FAX (000000100): FROM root@localhost TO XXXXXXXXXXXXX (docq/doc83.ps;1c00 sent in 0:00:13) Jul 29 04:18:27.19: [16256]: SEND FAX (000000100): FROM root@localhost TO XXXXXXXXXXXXX (page 1 of 1 sent in 0:00:13) Jul 29 04:18:28.19: [16256]: <-- [9:AT+FTH=3\r] Jul 29 04:18:28.21: [16256]: --> [7:CONNECT] Jul 29 04:18:28.21: [16256]: <-- HDLC<3:FF C8 DF> Jul 29 04:18:28.21: [16256]: <-- data [3] Jul 29 04:18:28.21: [16256]: <-- data [2] Jul 29 04:18:29.29: [16256]: --> [2:OK] Jul 29 04:18:29.29: [16256]: MODEM input buffering enabled Jul 29 04:18:30.29: [16256]: <-- [5:ATH0\r] Jul 29 04:18:30.31: [16256]: --> [2:OK] Jul 29 04:18:30.31: [16256]: MODEM set DTR OFF Jul 29 04:18:30.31: [16256]: MODEM set baud rate: 0 baud (flow control unchanged) Jul 29 04:18:30.31: [16256]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5) Jul 29 04:18:30.31: [16256]: SESSION END From: Lee Howard [mailto:fa...@ho...] Sent: Thursday, July 28, 2016 6:52 PM To: Joseph Jackson Cc: iax...@li... Subject: Re: [iaxmodem-users] Adjusting skew On 07/28/2016 02:27 PM, Joseph Jackson wrote: I did a pcap of the call and I'm able to hear both legs trying to negotiate the fax setup. Then it would seem that the audio is getting through. Assuming that you're using HylaFAX, what does the HylaFAX session log (/var/spool/hylafax/log/...) show? Thanks, Lee. |
From: Lee H. <fa...@ho...> - 2016-07-29 05:04:32
|
On 07/28/2016 09:20 PM, Joseph Jackson wrote: > > Jul 29 04:11:58.89: [15934]: <-- [18:ATDTXXXXXXXXXXXXX\r] > > Jul 29 04:12:57.74: [15934]: --> [10:NO CARRIER] > So, at that point you're going to need to get an audio recording because iaxmodem is simply saying that it doesn't detect fax tones in the call audio. Put "record" into your iaxmodem config file, restart iaxmodem, and then reproduce this "no carrier" result. Then, take /tmp/<device>-iax.raw and convert it to a wav file following the instructions in the README ... sox -s -w -r 8000 -c 1 ttyIAX-iax.raw playable.wav ... or ... sox -e signed-integer -b 16 -r 8000 -c 1 ttyIAX-iax.raw playable.wav Then listen to the wav file. If you can't hear the problem audibly then you'll need to open the file in a WAV editor such as audacity and *inspect* the audio to see if there are gaps (jitter) or something. Normally the problem will be obvious by listening, but not always. Thanks, Lee. |