broken-session-through-slmodem-2.9.11_pre20080817.log

session.log (text/plain), 21.72 KB, created by Martin Mokrejš on 2009-05-26 15:13:01 UTC

<198.521503> hw:1: run cmd: ATE0+GCI=2eS7=120S0=0L1V1x3&c0E1&d0M2\n3
<198.521596> main: alsa_ioctl: cmd 8, arg 1...
<198.521634> main: alsa_ioctl: cmd 8, arg 1...
<198.521663> hw:1: modem report result: 0 (OK)
<208.602913> hw:1: run cmd: atdt971103333,
<208.603001> hw:1: modem dial: t971103333,...
<208.603027> hw:1: modem_dial_start...
<208.603051> call: create...
<208.603084> CallProgFP_Create >>
<208.603108> APPLY_FILTER = 0
<208.603136> Detection Thresholds: levle_fix=34,--> LEVEL_THRESHOLD=285
<208.603162> ============> 0
<208.603186> Cadence: Busy Tone loose detection is 0
<208.603243> TYPE BUSY
<208.603319> Filter index 0
<208.603341> Filter SubIndex 0
<208.603363> MAX_ON_TIME 21 Buffers     MIN_ON_TIME 3 Buffers
<208.603388> MAX_OFF_TIME 30 Buffers    MIN_OFF_TIME 6 Buffers
<208.603411> OFF_TIME_THAT_RESETS_CYCLE 90
<208.603433> BUFFER LENGTH 160 samples.
<208.603455> INTEGRATION_LENGTH 0[ms]
<208.603477> LEVEL 285
<208.603502> INTEGRATION_TIME = 0 Buffers.
<208.603528> Detection Thresholds: levle_fix=34,--> LEVEL_THRESHOLD=285
<208.603553> TYPE DIAL
<208.603576> Filter index 0
<208.603598> Filter SubIndex 0
<208.603620> MAX_ON_TIME 0 Buffers     MIN_ON_TIME 0 Buffers
<208.603643> MAX_OFF_TIME 0 Buffers    MIN_OFF_TIME 0 Buffers
<208.603666> OFF_TIME_THAT_RESETS_CYCLE 0
<208.603688> BUFFER LENGTH 666 samples.
<208.603710> INTEGRATION_LENGTH 1400[ms]
<208.603732> LEVEL 285
<208.603755> INTEGRATION_TIME = 15 Buffers.
<208.603781> CALLPROG Create <<
<208.603804> CALLPROG Dialing t971103333,
<208.603828> Configuration->tone_DigitLength 100
<208.603851> Configuration->pulse_OffHookTime 40
<208.603874> Configuration->pulse_OnHookTime 60
<208.603896> Configuration->dialPauseTime 4
<208.603917> Configuration->flashTime 10
<208.603940> Configuration->toneOrPulseFlag 0
<208.603963> Configuration->dialModifierValidationFlag 1
<208.603987> Configuration->ABCD_PermittedFlag 0
<208.604010> Configuration->pulseAndToneInSameStringPermittedFlag 0
<208.604033> Configuration->callingToneFlag 1
<208.604056> Configuration->commaPauseDurLimit 30
<208.604079> Configuration->digitPattern 1
<208.604102> Configuration->tone_BetweenDigitsInterval 100
<208.604125> Configuration->pulse_BetweenDigitsInterval 800
<208.604150> DTMF_Gain1 = 13014
<208.604173> DTMF_Gain2 = 16384
<208.604196> AnalyzeDialString: Updated 17 May 1999 00:50
<208.604246> AnalyzeDialString: LAST_DIALABLE_SYMBOL is 9
<208.604270> Dial String Syntax is VALID
<208.604294> GetNoAnswerTimeOut. 120
<208.604317> BlindCall: GetBlindDialPause = 2 .
<208.604339> CALLPROG_Dial was exited.
<208.604361> call: create RC: 9600 <-> 8000...
<208.604387> hw:1: modem_start..
<208.604409> hw:1: modem set state: 1 --> 2...
<208.604433> hw:1: new state: DP_ESTAB
<208.604455> hw:1: modem set hook: 0 --> 1...
<208.604477> main: alsa_ioctl: cmd 2, arg 1...
<208.604537> main: alsa_ioctl: cmd 11, arg 0...
<208.604655> main: alsa_ioctl: cmd 4, arg 2580...
<208.604682> main: alsa_ioctl: cmd 7, arg 30...
<208.604706> main: alsa_start...
Hardware PCM card 1 'Intel 82801CA-ICH3 Modem' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 1
  rate         : 9600
  exact rate   : 9600 (9600/1)
  msbits       : 16
  buffer_size  : 1536
  period_size  : 48
  period_time  : 5000
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 48
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 1536
  silence_threshold: 0
  silence_size : 0
  boundary     : 1610612736
  appl_ptr     : 0
  hw_ptr       : 0
Hardware PCM card 1 'Intel 82801CA-ICH3 Modem' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 1
  rate         : 9600
  exact rate   : 9600 (9600/1)
  msbits       : 16
  buffer_size  : 1536
  period_size  : 48
  period_time  : 5000
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 48
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 1536
  silence_threshold: 0
  silence_size : 0
  boundary     : 1610612736
  appl_ptr     : 0
  hw_ptr       : 0
<208.605556> main: startup write: 384...
<208.610871> call: process: msg 18 --> 0
<210.205625> DCR: initial DC Evaluation done, DC level 257, enabled
<210.610616> CALLPROG: Time out
<210.610661> STATE:  CALLPROG_WAIT_DIAL --> CALLPROG_DIALING
<210.610703> call: process: msg 0 --> 3
<210.615682> DIALER_INITIAL_STATE
<210.615724> Digit is t
<210.615748> Dialer.c: GetNextDigit... TONE_OR_PULSE_FLAG became TONE_DIALING
<210.615772> Digit is 9
<210.615795> Samples left = 800
<210.615840> call: process: msg 3 --> 0
<210.710603> Done Generating digit
<210.810589> Done Generating silence between digits
<210.810626> Digit is 7
<210.810650> Samples left = 800
<210.910596> Done Generating digit
<211.010568> Done Generating silence between digits
<211.010617> Digit is 1
<211.010641> Samples left = 800
<211.110573> Done Generating digit
<211.210553> Done Generating silence between digits
<211.210597> Digit is 1
<211.210622> Samples left = 800
<211.310543> Done Generating digit
<211.410523> Done Generating silence between digits
<211.410567> Digit is 0
<211.410591> Samples left = 800
<211.510516> Done Generating digit
<211.610507> Done Generating silence between digits
<211.610546> Digit is 3
<211.610569> Samples left = 800
<211.710497> Done Generating digit
<211.810483> Done Generating silence between digits
<211.810525> Digit is 3
<211.810549> Samples left = 800
<211.910501> Done Generating digit
<212.010462> Done Generating silence between digits
<212.010504> Digit is 3
<212.010527> Samples left = 800
<212.110461> Done Generating digit
<212.210447> Done Generating silence between digits
<212.210487> Digit is 3
<212.210511> Samples left = 800
<212.310440> Done Generating digit
<212.310480> Digit is ,
<212.310504> Consequitive-Commas Dialing; Number of samples is 32000.
<216.310031> Done Generating Dial-Pause
<216.315073> DIALER_END_STATE
<216.315113> STATE:  CALLPROG_DIALING --> CALLPROG_WAIT_RING
<216.315155> call: process: msg 0 --> 4
<216.320104> call: process: msg 4 --> 0
<220.069668> Found 2100
<220.069726> call: process: msg 0 --> 16
<220.069752> hw:1: 110016: change dp: --> 8...
<220.069779> v8: create: caller 1, automode 0, dp id 92.
<220.069811> V8: Create called, V8 version 23/09/03 .
<220.069836> ############################################################
<220.069860> V8: local configuration : 
<220.069882>    Side = Caller
<220.069907>    Operation Mode = 0
<220.069931>    Modulations - V90=1, V34=1, V34HD=0, V32=1, V22=0, V17=0, V29=0, V27=0, V23=0, V21=0
<220.069962>    Call Functions - Data=1, CallRxFax=0, CallTxFax=0, V.80=0
<220.069989>    Protocol - LAPM V.42
<220.070013>    v8bisIndication - 0
<220.070037>    timeouts - signal detect 12 sec, message detect 7 sec
<220.070064>    quickConnectEnabled - 1
<220.070089>    lapmIndication - 1
<220.070113>    ucodeForQts - 9
<220.070137>    ansPcmLevel - 0
<220.070161> ############################################################
<220.070191> V8: Initial CM message length is 9 octets
<220.070243> call: delete...
<220.070266> Dialer was aborted.
<220.070288> CALLPROG_Delete is entered
<220.070310> cadence_delete with CADENCE_DIAL_OBJ is invoked
<220.070335> cadence_delete with CADENCE_OBJ is invoked
<220.070358> CALLPROG_Delete is exited
<220.074732> V8: State changed from V8_INIT to V8_ORG_WAITING_FOR_ANSAM
<220.074783> v8: status (6) V8_ORG_WAITING_FOR_ANSAM
<220.194703> V8: State changed from V8_ORG_WAITING_FOR_ANSAM to V8_ORG_ANSAM_DETECTED_WAITING_TE
<220.194752> v8: status (7) V8_ORG_ANSAM_DETECTED_WAITING_TE
<221.044565> ANSAM phase reversals detected delay = 449
<221.044611> ANSAM phase reversals detected delay = 449
<221.044635> ANSAM phase reversals detected delay = 449
<221.199522> V8 ANSAM Detected (CM ready)
<221.199630> V8: State changed from V8_ORG_ANSAM_DETECTED_WAITING_TE to V8_ORG_SEND_QC
<221.199658> v8: status (14) V8_ORG_SEND_QC
<221.399567> V8: State changed from V8_ORG_SEND_QC to V8_ORG_SEND_CM
<221.399612> v8: status (8) V8_ORG_SEND_CM
<221.734506> V8:  QCA1d: Got Good QCA1d !!!!
<221.734552> V8:  QCA1d: ANSpcm level index: bits27-28 = 1, bits57-58 = 1
<221.734581> V8: State changed from V8_ORG_SEND_CM to V8_OK
<221.734608> v8: process: OK.
<221.734630> V8Report: Finished with Quick Connect
<221.734653> v8: process: QC.
<221.734677> main: alsa_ioctl: cmd 10, arg 0...
<221.734701> main: delay = 424
<221.734724> v8: Link established. Idle timer 1096.
<221.734747> v8: status (13) V8_OK
<221.734770> hw:1: 126000: change dp: --> 92...
<221.734795> vpcm: create: dp 92, caller 1, frag 48 (size 53848).
<221.734874> VPCMXF_Create: side is Analog, maxDataBuffer - 48
<221.734910> V90Modem Construction (as Analog Modem)
<221.734956> $!$ 6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A1F3?????
<221.735003> $!$ 6@4A3C5?:A6@4A3955:766473955:7667;7A9>?:668@8<55>866776;7>==877;5>55?=:;998<9>>F:D473955:766473955:76@4A3C5?:A6@4A1F3?????
<221.735050> $!$ 6@4A3C5?:A6@4A3955:766477?9D?9669;7A9::7;;9:7>55>F:<476<7A:78:7:6955>>;88F8>:5:7:E8E7E:>:766473955:76@4A3C5?:A6@4A1F3?????
<221.735074> *********************************************************
<221.735098> V90Modem Version: 2.98  (25-Mar-04)
<221.735121> *********************************************************
<221.735152> $!$ 9<5@497B>F::8<7F55==:;998<9>>F:D475=9:?::9997B:5?;:?8F7G6?8D4@????
<221.735227> $!$ 8C8F7=9>>=:?8<7=55=8;;8@7<9@:7898F7G9C><:99;39:<>@;:8?7H::?;666D7>9B>F;89@395@:79:997:9>>E667;7B9B><664B3978>F:D9:8=9:>C66777H:<><;82D1C????
<221.735268> $!$ 898F7F:5>F:D8<7G:9?:7@475?9A>F;88<7::9:C66685=7>:C66685<79:C666E7>:<:7886C5E3B8A????
<221.735293> *********************************************************
<221.735319> V90Parameters: upStream min rate : 4800 upStream max rate : 4800  Rate mask :1
<221.735361> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C976987:77C47493B8A????
<221.735397> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C9769:7>F:88<396B:7762D1C????
<221.735466> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C975<9D>E:D8<7<:9>@:E8E6=:>?7:;474F55;74C2A????
<221.735517> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9?9:D597=8D>D:;887G8D><;8997H:7=F;99;7=8D><;<887E::>8;:8@7H9C=F:;8E7:97>C:;474F55;84C2A????
<221.735553> V90PreFilter: HardwareCodecType: AMR_SILABS
<221.736871> $!$ 9<5@4987><;9887F:5>C:;994C55?:;:888=9::77C475?87<F9@6<5G3B8A????
<221.737136> V90ConnectionEvaluator reset called !
<221.737175> $!$ 664A3C5?:A6@4A3C5?:A6@4A397:>::>8F3987?9:D475F9:>::>887G9>?::C473C5?:A6@4A3C5?:A6@4A3C558A????
<221.737237> V90Phase3Demodulator: Reset called, sessionFlag = 1 !
<221.737286> V90Phase3Demodulator: initial state set to WaitForSd
<221.737341> $!$ 9<5@497:?8;;887E9>?A:;994C55<:;88<7::9><::473F55<D8C7?399B>F::8<399>?:668;7B:8>8:88C7>99:E4C2A????
<221.737374> $!$ 9<5@497:?8;;887E9>?A:;994C55?9:;9:7>:98D4@????
<221.737411> $!$ 9<5@497:?8;;887E9>?A:;994C55<C8;475;9:?;:7474F55:D764E4965;776577>5B;8762D1C????
<221.737448> $!$ 9<5@497:?8;;887E9>?A:;994C55<;8<6<3977><;:88396B:76C573G65;77657499::D7=2D1C????
<221.737516> V92Modem Construction (as Analog Modem)
<221.737561> $!$ 6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A1F3?????
<221.737606> $!$ 6@4A3C5?:A6@4A3955:766473955:7667;7A9>?:668@8<55>866776;7>==877;5>55?=:;998<9>>F:D473955:766473955:76@4A3C5?:A6@4A1F3?????
<221.737651> $!$ 6@4A3C5?:A6@4A3955:766477?9D?9669;7A9::7;;9:7>55>F:<476<7A:78:7:6955>>;88F8>:5:7:E8E7E:>:766473955:76@4A3C5?:A6@4A1F3?????
<221.737675> *********************************************************
<221.737699> V92Modem Version: 1.1  (9-Apr-01)
<221.737722> *********************************************************
<221.737753> $!$ 9<5@4;7B>F::8<7F55==:;998<9>>F:D475=9:?::9997B:5?;:?8F7G6?8D4@????
<221.737791> $!$ 8C8<7F9D?9;?477<9A><:78E8>:5?:664B3999>@:B477=9:?::9997B:5?;:E993998?9:79:7A55>=:?9?1F3?????
<221.737835> $!$ 6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A3C5?:A6@4A1F3?????
<221.737931> V92Modulator constraction
<221.739541> $!$ 9<5@4;85>?:79:7>68<D:E8;8>9A>8;:8F8;6?:79:795G66?<669:8=96?;:;477E9:>E:=9;7A55?::;9;39:9>F66594965;77:2D1C????
<221.739574> V92Modulator reset
<221.739620> V92EchoCanceller: constraction
<221.739656> $!$ 9<5@4;7:>::>8F5<96>E:98<7E9A><;85A399:>::>8F5=9:>C:79@39::?7::888=9:>;669;7H6?:77>5;493?????
<221.739694> $!$ 9<5@4;7:>::>8F5<96>E:98<7E9A><;85A399:>::>8F5?9>>C;:8<8;7A><:D474F55;87>571F3?????
<221.739738> $!$ 9<5@4;7:>::>8F5<96>E:98<7E9A><;85A399:>::>8F5;9:?;:7474F55:D764E4965;77657493B8A????
<221.739777> $!$ 9<5@4;7:>::>8F5<96>E:98<7E9A><;85A399:>::>8F5;9:?;:76;7>98>8;?474F55:D764E4965;77657493B8A????
<221.739826> vpcm: VPCM rate limits: 300-56000
<221.739850> main: alsa_ioctl: cmd 10, arg 0...
<221.739872> main: delay = 424
<221.739893> vpcm: Delays: HW 244, DMA 580
<221.739914> vpcm: initial dp V.92, session type 2.
<221.739936> VPcmV34Create: quick connect indication from phase1 = 1
<221.739958> VPcmV34Create: Uqts index is 9
<221.739980> VPcmV34Create: ANSpcm level index is 1
<221.740001> VPcmV34Create, initial Session Type = 2
<221.740022> RX at 815C7C0
<221.740084> On Create: Setting desired TX MD (0 mSec)!
<221.740108> V90Parameters: upStream min rate : 4800 upStream max rate : 33600  Rate mask :1fff
<221.740147> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C976987:77C47493B8A????
<221.740182> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C9769:7>F:88<396B:7762D1C????
<221.740281> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C975<9D>E:D8<7<:9>@:E8E6=:>?7:;474F55;74C2A????
<221.740330> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9?9:D597=8D>D:;887G8D><;8997H:7=F;99;7=8D><;<887E::>8;:8@7H9C=F:;8E7:97>C:;474F55;84C2A????
<221.740355> V90_V34_Main: reinitializing parameters.
<221.740377> V90ConnectionEvaluator reset called !
<221.740412> $!$ 664A3C5?:A6@4A3C5?:A6@4A397:>::>8F3987?9:D475F9:>::>887G9>?::C473C5?:A6@4A3C5?:A6@4A3C558A????
<221.740435> V90Phase3Demodulator: clearVerificationStatus called
<221.740456> V90_V34_Main: external reset called.
<221.740478> V90Demodulator: Enter Channel Verification called !
<221.740499> V90Demodulator reset, quick connect flag = 1
<221.740537> $!$ 9<5@4979><:C8F7=::>C:79;7H:7:7;88<8<9:?;7@475;96?<::475H9;>=;98<8=55;D664D495C;776571F3?????
<221.740569> $!$ 9<5@4987><;9887F:5>C:;994C55?:;:888=9::77C475?87<F9@6<5G3B8A????
<221.740598> $!$ 9<5@497:?8;;887E9>?A:;994C55?9:;9:7>:98D4@????
<221.740632> $!$ 9<5@497:?8;;887E9>?A:;994C55<C8;475;9:?;:7474F55:D764E4965;776577>5B;8762D1C????
<221.740667> $!$ 9<5@497:?8;;887E9>?A:;994C55<;8<6<3977><;:88396B:76C573G65;77657499::D7=2D1C????
<221.740733> V90Phase3Demodulator: clearVerificationStatus called
<221.740756> V90Phase3Demodulator: Reset called, sessionFlag = 1 !
<221.740803> V90Phase3Demodulator: initial state set to WaitForQTS
<221.740851> $!$ 9<5@497:?8;;887E9>?A:;994C55><:D9;7>:7<::>887G9C><:B7=7>:7>@:<8@7<96?;:?8F7G3B8A????
<221.740884> $!$ 9<5@4987><;9887F:5>C:;994C55?:;:888=9::77C476987<<9E685G88=7896D1F3?????
<221.740921> $!$ 9<777<9B==795;6<9:?;9:9?6<98>8:B8<4C55?;;>478<98>8:B8<39:8><;:478=9D:77;5>4B688D4@????
<221.740944> V34SetupModulator: baudrate 2400, carrier 1800, preemp 0, V90=0. fullReset=0
<221.740972> V34SetupDemodulator: baudrate 2400, carrier 1800
<221.740995> V34SetupModulator: baudrate 600, carrier 2400, preemp 0, V90=0. fullReset=1
<221.741029> V34FLO: Echo running in Original Integer...
<221.741051> V34FLO: Echo running in Original Integer...
<221.741076> V34HSHAKE: txstate NOSTATE0=>SILENCEINFO(rx NOSTATE0, mst NOSTATE0, [1]0, [2]0)
<221.741101> V34HSHAKE: rxstate NOSTATE0=>RX_DPSK(tx SILENCEINFO, mst NOSTATE0, [1]0, [2]0)
<221.741126> V34HSHAKE: microstate NOSTATE0=>DET_SYNC(tx SILENCEINFO, rx RX_DPSK, [1]0, [2]0)
<221.741150> V90, setINFO0dBits
<221.741171> V90ConstellationDesigner: set min rate to 300
<221.741192> V90ConstellationDesigner: set max rate to 56000
<221.741240> VPcmV34Main: minLevel given is 0 , minSigLevel set to 101
<221.744384> V34 filtdelay set to 95 (params initial delay = 244)
<221.744446> V34FEC, V34dmadelay set to 972, (ext delay=580)
<221.744485> $!$ 9<5@4;7:>::>8F5<96>E:98<7E9A><;85A399:>::>8F5=9:>C:79@39::?7::888=9:>;669;7H6?:77<5?4=3?????
<221.744507> VPcmFlo: From Stream - Entrance Filter forced disabled...
<221.744532> VPcmFlo: YES! entrance filter applied = 0
<221.744555> v8: delete...
<221.744623> main: change delay -96...
<221.749462> main: change delay -48...
<221.754465> main: change delay -40...
<221.754618> vpcm: New status 10
<221.754641> vpcm: Same Line Verification Status
<221.809584> $!$ 9<5@4985>?:79:7>68<;:;8D7H99?<:B888=9D?97@476:89=:668;7>:9><:99;7>99:786474=68;:4C2A????
<221.819580> $!$ 9<5@4985>?:79:7>68<;:;8D7H99?<:B888=9D?97@476:89=:8D8F8=55>;:;9;7>98?;:;8;3975:77=5@1F3?????
<221.824624> $!$ 9<5@4985>?:79:7>68<;:;8D7H99?<:B888=9D?97@477>9C?;:;993976<E99977<9B:7::8<7F9D>;669:8=96?;:;2D1C????
<221.824674> $!$ 9<5@4987><;9887F:5>C:;994C55?:;:888=9::77C475?87<F9@6<5G3B8A????
<221.924570> VPcmFloModem (QC LineVerify): ANSpcm demod over (after 1640 samples), start TONEq...
<221.924616> VPcmFloModem (QC LineVerify): Channel verification status is: 1
<221.924658> $!$ 9<5@4985>?:79:7>68<;:;8D7H99?<:B888=9D?97@477>9C?;:;99398<>8:?9;5?9D?9876E6<:5>::C6;8;9D?74C2A????
<221.929553> $!$ 9<5@4985>?:79:7>68<;:;8D7H99?<:B888=9D?97@475:7C=:;68:7F55><:D8<8;9<?@668;8;9D?7668;7>:9><:99;7>99:E6D4E1F3?????
<221.929673> VPcmFloModem (QC LineVerify): TONEq termination requested, still bellow 50mS (nof samples = 48)...
<221.974564> VPcmFloModem (QC LineVerify): TONEq mod over (after 480 samples), tx silence...
<222.014552> VPcmFloModem (QC LineVerify): Silence after TONEq over, move to phase2...
<222.014596> VPcmV34Main: Line verification period completed !!!
<222.014621> VPcmV34Main: Moving to full phase2 upon DP Manager setting...
<222.014646> V90Parameters: upStream min rate : 4800 upStream max rate : 33600  Rate mask :1fff
<222.014690> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C976987:77C47493B8A????
<222.014728> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C9769:7>F:88<396B:7762D1C????
<222.014768> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9><:C975<9D>E:D8<7<:9>@:E8E6=:>?7:;474F55;74C2A????
<222.014818> $!$ 9<5@4985>8;8887F9:?;:;998<6?:78:8<7;::>>664D39:9?9:D597=8D>D:;887G8D><;8997H:7=F;99;7=8D><;<887E::>8;:8@7H9C=F:;8E7:97>C:;474F55;84C2A????
<222.014857> vpcm: New status 0
<222.014880> vpcm: Re-starting phase II
<222.024449> V34HSHAKE: txstate SILENCEINFO=>TX_DPSK(rx RX_DPSK, mst DET_SYNC, [1]10, [2]0)
<222.024497> setINFO0aBits - setting info0a for V.PCM
<222.024521> ...indicating V.92 capabilities...
<222.109534> V34HSHAKE: txstate TX_DPSK=>TONE_AB(rx RX_DPSK, mst DET_SYNC, [1]0, [2]0)
<222.254554> VPcmV34Main: Masking CAS detection after 4808 in train...
<223.559294> V34HSHAKE: txstate TONE_AB=>TX_DPSK(rx RX_DPSK, mst DET_SYNC, [1]0, [2]0)
<223.559347> errorrecovery is initialized in DET_SYNC
<224.369270> V34HSHAKE: microstate DET_SYNC=>DET_INFO(tx TX_DPSK, rx RX_DPSK, [1]0, [2]0)
<224.369319> DET_SYNC is received in RX_DPSK,rx->gain=0x2f82
<224.444302> V34INFO, info0 CRC not received properly in DET_INFO
<224.444347> V34HSHAKE: microstate DET_INFO=>DET_SYNC(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<224.444378> SetINFO0dBits  
<226.709107> V34HSHAKE: microstate DET_SYNC=>DET_INFO(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<226.709161> DET_SYNC is received in RX_DPSK,rx->gain=0x6a4e
<226.784091> V34INFO, info0 CRC not received properly in DET_INFO
<226.784139> V34HSHAKE: microstate DET_INFO=>DET_SYNC(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<226.784167> SetINFO0dBits  
<226.889094> V34HSHAKE: microstate DET_SYNC=>DET_INFO(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<226.889174> DET_SYNC is received in RX_DPSK,rx->gain=0x6a4e
<226.969028> V34INFO, info0 CRC not received properly in DET_INFO
<226.969073> V34HSHAKE: microstate DET_INFO=>DET_SYNC(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<226.969101> SetINFO0dBits  
<232.623401> V34HSHAKE: microstate DET_SYNC=>DET_INFO(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<232.623456> DET_SYNC is received in RX_DPSK,rx->gain=0x1526
<232.703489> V34INFO, info0 CRC not received properly in DET_INFO
<232.703534> V34HSHAKE: microstate DET_INFO=>DET_SYNC(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<232.703562> SetINFO0dBits  
<233.943270> V34HSHAKE: microstate DET_SYNC=>DET_INFO(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<233.943323> DET_SYNC is received in RX_DPSK,rx->gain=0x1526
<234.023290> V34INFO, info0 CRC not received properly in DET_INFO
<234.023335> V34HSHAKE: microstate DET_INFO=>DET_SYNC(tx TX_DPSK, rx RX_DPSK, [1]0, [2]46)
<234.023363> SetINFO0dBits  
<237.018083> vpcm: train timeout!
<237.018130> vpcm: Link Error
<237.018153> hw:1: modem_update_status: 4
<237.018179> hw:1: --> FINISH.
<237.018226> hw:1: modem_hup...
<237.018251> hw:1: modem set state: 2 --> 9...
<237.018275> hw:1: new state: DP_DISC
<237.018310> hw:1: modem_stop..
<237.018331> main: alsa_stop...
<237.018387> hw:1: modem set hook: 1 --> 0...
<237.018413> main: alsa_ioctl: cmd 2, arg 0...
<237.018474> vpcm: delete...
<237.018555> $!$ 9<5@4979><:C8F7=::>C:79;7H:7:7:E8E39:8><;99:7B9D>E9:8<8;9B>@:D888=9>>F:D5A3989>@:C8@7G9<:7:E8=7?:8><;:475G7D=;669:7::;><::478=9D:7;88<7@9>?:;:998B55:?:?9:5=96?;:77:8=96?;:;474F55;76B477B:8<<:?884?55;D66573B3B8A????
<237.018583> V90Phase3Demodulator: clearVerificationStatus called
<237.018612> V92EchoCanceller Destruction
<237.018638> V92Modem Destruction
<237.018682> V90Modem Destruction
<237.018760> $!$ 9<5@4979><:C8F7=::>C:79;7H:7:7:E8E39:8><;99:7B9D>E9:8<8;9B>@:D888=9>>F:D5A3989>@:C8@7G9<:7:E8=7?:8><;:475G7D=;669:7::;><::478=9D:7;88<7@9>?:;:998B55:?:?9:5=96?;:77:8=96?;:;474F55;76B477B:8<<:?884?55;D66573B3B8A????
<237.018786> V90Phase3Demodulator: clearVerificationStatus called
<237.018959> hw:1: modem set state: 9 --> 1...
<237.018986> hw:1: new state: MODEM_IDLE
<237.019009> hw:1: modem report result: 3 (NO CARRIER)
<237.019042> main: dev write = 0