[cisco-voip] Debugging ephone busy
Alain RICHARD
alain.richard at equation.fr
Fri Apr 9 12:52:16 EDT 2010
I am experiencing a strange problem with an UC520 (version 8.0.2) and 7942 phones.
At random occasion, a call to a phone get an immediate busy tone although the phone is not busy. Generally, a second try in the next few seconds will make the called phone rings.
I sort out the problem, I have investigated a call from a 7945 phone 0026.99EF.9CAE to a 7942 phone 0026.99ED.A429 :
ipbx1#sh ephone 0026.99EF.9CAE
ephone-7[6] Mac:0026.99EF.9CAE TCP socket:[24] activeLine:0 whisperLine:0 REGISTERED in SCCP ver 17/17 max_streams=5
mediaActive:0 whisper_mediaActive:0 startMedia:0 offhook:0 ringing:0 reset:0 reset_sent:0 paging 0 debug:1 caps:9
IP:10.246.100.43 * 20522 7945 keepalive 2973 max_line 2 available_line 2
button 1: cw:1 ccw:(0 0)
dn 11 number 237 CH1 cc(03) IDLE CH2 cc(03) IDLE shared with monitor-ring
button 2: cw:1 ccw:(0 0)
dn 39 number 230 CH1 cc(03) IDLE CH2 cc(03) IDLE monitor-ring shared
Preferred Codec: g711ulaw
Lpcor Type: none Username: arichard Password: xxxxxx
ipbx1#sh ephone 0026.99ED.A429
ephone-8[7] Mac:0026.99ED.A429 TCP socket:[15] activeLine:0 whisperLine:0 REGISTERED in SCCP ver 17/17 max_streams=5
mediaActive:0 whisper_mediaActive:0 startMedia:0 offhook:0 ringing:0 reset:0 reset_sent:0 paging 0 debug:1 caps:9
IP:10.246.100.30 * 29165 7942 keepalive 205 max_line 2 available_line 2
button 1: cw:1 ccw:(0 0)
dn 13 number 231 CH1 cc(03) IDLE CH2 cc(03) IDLE shared with monitor-ring
Preferred Codec: g711ulaw
Lpcor Type: none Username: jmterrat Password: xxxxxx
And in about 20% a of cases, I get an immediate busy tone when calling 231 from 237. I have placed the two phones on the UC520 switch in order to be sure it is not a network issue with the same result. And I am sure the phone is effectively not busy.
Using :
ipbx1#debug ephone detail mac-address 0026.99EF.9CAE
ipbx1#debug ephone detail mac-address 0026.99ED.A429
I get :
033246: Apr 9 15:28:50.563: ephone-7[6/24][SEP002699EF9CAE]:SoftKeyEventMessage event 2 line 0 callref 0
033247: Apr 9 15:28:50.563: ephone-7[6/24][SEP002699EF9CAE]:SK NEWCALL line 0 ref 0
033248: Apr 9 15:28:50.563: ephone-7[6/24][SEP002699EF9CAE]:
033249: Apr 9 15:28:50.563: bulk_speeddial_init_ephone: 6
033250: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:SkinnyRestartTransferCollect for line 0 chan 1
033251: Apr 9 15:28:50.567: ephone-7[6/24]:SkinnyRestartTransferCollect ignored
033252: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 IDLE
033253: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033254: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 2 IDLE
033255: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033256: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 1 IDLE
033257: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033258: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 2 IDLE
033259: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033260: Apr 9 15:28:50.567: ephone-7[6/24]:OFFHOOK
033261: Apr 9 15:28:50.567: ephone-7[6/24]:---SkinnySyncPhoneDnOverlays is onhook
033262: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:
033263: Apr 9 15:28:50.567: bulk_speeddial_init_ephone: 6
033264: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:Set FAC enabled (1) and dial mode (0)
033265: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 IDLE
033266: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033267: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 2 IDLE
033268: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033269: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 1 IDLE
033270: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033271: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 2 IDLE
033272: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033273: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:SEIZE on activeLine 0 activeChan 1
033274: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 IDLE
033275: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033276: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:Seize auto select line 1 chan 1
033277: Apr 9 15:28:50.567: ephone-7[6/24]:UpdateCallState DN 11 chan 1 state 2 calleddn -1 chan 1
033278: Apr 9 15:28:50.567: ephone-7[6/24]:Binding ephone-7 to DN 11 chan 1 s2s:0
033279: Apr 9 15:28:50.567: Assign Call Ref 1353 to DN 11 chan 1
033280: Apr 9 15:28:50.567: Skinny Call State change for DN 11 chan 1 SIEZE from IDLE
033281: Apr 9 15:28:50.567: ephone-(7) DN 11 chan 1 calledDn -1 chan 1 callingDn -1 chan 1 :: port=0
033282: Apr 9 15:28:50.567: SkinnyUpdateCstate DN 11 chan 1 cstate 1
033283: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 SIEZE
033284: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033285: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 SIEZE
033286: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033287: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 2 IDLE
033288: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033289: Apr 9 15:28:50.567: DN 11 chan 1 ephone-1 state set to RemoteMultiline
033290: Apr 9 15:28:50.567: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[-1]
033291: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 1 IDLE
033292: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033293: Apr 9 15:28:50.567: SkinnyGetCallState for DN 39 chan 2 IDLE
033294: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033295: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 1 SIEZE
033296: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033297: Apr 9 15:28:50.567: SkinnyGetCallState for DN 11 chan 2 IDLE
033298: Apr 9 15:28:50.567: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033299: Apr 9 15:28:50.567: DN 11 chan 1 ephone-5 state set to RemoteMultiline
033300: Apr 9 15:28:50.567: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[-1]
033301: Apr 9 15:28:50.567: ephone-7[6/24][SEP002699EF9CAE]:UpdateCState select phone for DN 11 instance 3
033302: Apr 9 15:28:50.567: ephone-7[6/24]:SkinnyUpdateCState activeLine 1 chan 1 DN 11 ref 1353
033303: Apr 9 15:28:50.571: ephone-7[24]:SetCallState line 1 DN 11(-1) chan 1 ref 1353 TsOffHook
033304: Apr 9 15:28:50.571: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[-1]
033305: Apr 9 15:28:50.571: ephone-7[6/24]:SkinnyTrackActiveCall add line 1 ref 1353 state 1 (slot 0)
033306: Apr 9 15:28:50.571: ephone-7[6/24][SEP002699EF9CAE]:ClearCallPrompt line 1 ref 1353
033307: Apr 9 15:28:50.571: ephone-7[6/24]:SelectPhoneSoftKeys set 4 mask FFFF for line 1 ref 1353
033308: Apr 9 15:28:50.571: SkinnyGetCallState for DN 11 chan 1 SIEZE
033309: Apr 9 15:28:50.571: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033310: Apr 9 15:28:50.571: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033311: Apr 9 15:28:50.571: SkinnyGetCallState for DN 11 chan 1 SIEZE
033312: Apr 9 15:28:50.571: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033313: Apr 9 15:28:50.571: ephone-7[6/24]:SpeakerPhoneOffHook
033314: Apr 9 15:28:50.571: ephone-7[6/24][SEP002699EF9CAE]:phone: 6
033315: Apr 9 15:28:50.571: ephone-7[6/24]:video_caps_count is zero
033316: Apr 9 15:28:50.583: SetDnCodec DN 11 chan 1 codec 4:G711Ulaw64k vad 0 size 160
033317: Apr 9 15:28:50.583: DN 11 chan 1 Voice_Mode
033318: Apr 9 15:28:50.583: SkinnyGetCallState for DN 11 chan 1 SIEZE
033319: Apr 9 15:28:50.583: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033320: Apr 9 15:28:50.583: SkinnyTransfereeHairpinRinging: dn 11 chan 1 tonetype 33
033321: Apr 9 15:28:50.583: dn_tone_control DN=11 chan 1 tonetype=33:DtInsideDialTone onoff=1 pid=284
033322: Apr 9 15:28:50.583: SkinnyGetCallState for DN 11 chan 1 SIEZE
033323: Apr 9 15:28:50.583: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033324: Apr 9 15:28:50.583: SkinnyGetCallState for DN 11 chan 1 SIEZE
033325: Apr 9 15:28:50.583: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033326: Apr 9 15:28:50.583: ephone-7[6/24]:CallPrompt line 1 ref 1353:tag 132 (Enter Number)
033327: Apr 9 15:28:50.583: ephone-7[6/24][SEP002699EF9CAE]:is_auto_local 0 for DN 11
033328: Apr 9 15:28:50.583: ephone-7[6/24][SEP002699EF9CAE]:SkinnySetToneRef callRef 0x549 tone 0x21
033329: Apr 9 15:28:50.583: ephone-7[6/24]:SkinnyPhoneTone: StartTone sent: normal line=1 ref=1353 tone=0x21
033330: Apr 9 15:28:50.583: Skinny StartTone 33 sent on ephone socket [24] DtInsideDialTone
033331: Apr 9 15:28:50.635: ephone-7[6/24][SEP002699EF9CAE]:MediaPathEventMessage Speaker ON
033332: Apr 9 15:28:50.635: ephone-7[6/24]:MediaPathEventMessage
033333: Apr 9 15:28:50.879: ephone-7[6/24][SEP002699EF9CAE]:OFFHOOK with called party 231
033334: Apr 9 15:28:50.879: ephone-7[6/24][SEP002699EF9CAE]:Fake redial to 231
033335: Apr 9 15:28:50.879: ephone-7[6/24][SEP002699EF9CAE]:Normal ReDial press 231 line 1
033336: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:KeypadButtonMessage 2
033337: Apr 9 15:28:51.079: ephone-7[6/24]:Entering FAC code
033338: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:First fac digit received 2
033339: Apr 9 15:28:51.079: SkinnyGetCallState for DN 11 chan 1 SIEZE
033340: Apr 9 15:28:51.079: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033341: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:is_auto_local 0 for DN 11
033342: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:SkinnyGetToneRef toneRef 0x549 callRef 0x549
033343: Apr 9 15:28:51.079: ephone-7[6/24]:SkinnyPhoneTone: StopTone sent: normal line=1 ref=1353 tone=0x0
033344: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:Not matched at first digit 2
033345: Apr 9 15:28:51.079: ephone-7[6/24]:
033346: Apr 9 15:28:51.079: bulk_sd_search_lists:Entry: digit:2, prefix= # state=1, index= 0
033347: Apr 9 15:28:51.079: ephone-7[6/24]:
033348: Apr 9 15:28:51.079: bulk_sd_search_lists:Exit : digit:2, prefix= # state=7, index= 1, retval = 1
033349: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:
033350: Apr 9 15:28:51.079: bulk_speeddial_check_new_digit: button= 2 state FAIL_MATCH
033351: Apr 9 15:28:51.079: SkinnyGetCallState for DN 11 chan 1 SIEZE
033352: Apr 9 15:28:51.079: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033353: Apr 9 15:28:51.079: SkinnyGetCallState for DN 11 chan 1 SIEZE
033354: Apr 9 15:28:51.079: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033355: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:Store ReDial digit: 2
033356: Apr 9 15:28:51.079: ephone-7[6/24]:SkinnyTryCall to 2 instance 1 start at 0 secondary 0
033357: Apr 9 15:28:51.079: dn_tone_control DN=11 chan 1 tonetype=0:DtSilence onoff=0 pid=284
033358: Apr 9 15:28:51.079: SkinnyGetCallState for DN 11 chan 1 SIEZE
033359: Apr 9 15:28:51.079: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033360: Apr 9 15:28:51.079: SkinnyGetCallState for DN 11 chan 1 SIEZE
033361: Apr 9 15:28:51.079: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033362: Apr 9 15:28:51.079: ephone-7[6/24][SEP002699EF9CAE]:is_auto_local 0 for DN 11
033363: Apr 9 15:28:51.079: ephone-7[6/24]:Tone Off ignored - already sent
033364: Apr 9 15:28:51.167: ephone-8[7/15][SEP002699EDA429]:SkinnyCheckPendingCallBackPhone scan 2 lines
033365: Apr 9 15:28:51.279: ephone-7[6/24][SEP002699EF9CAE]:KeypadButtonMessage 3
033366: Apr 9 15:28:51.279: ephone-7[6/24]:Entering FAC code
033367: Apr 9 15:28:51.279: ephone-7[6/24]:At fac_dial NOMATCHED/NORMAL state
033368: Apr 9 15:28:51.279: ephone-7[6/24]:
033369: Apr 9 15:28:51.279: bulk_sd_search_lists:Entry: digit:3, prefix= # state=7, index= 1
033370: Apr 9 15:28:51.279: ephone-7[6/24][SEP002699EF9CAE]:
033371: Apr 9 15:28:51.279: bulk_sd_search_lists: button= 3 state NOT_IN_SD
033372: Apr 9 15:28:51.279: SkinnyGetCallState for DN 11 chan 1 SIEZE
033373: Apr 9 15:28:51.279: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033374: Apr 9 15:28:51.279: SkinnyGetCallState for DN 11 chan 1 SIEZE
033375: Apr 9 15:28:51.279: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033376: Apr 9 15:28:51.279: ephone-7[6/24][SEP002699EF9CAE]:Store ReDial digit: 23
033377: Apr 9 15:28:51.279: ephone-7[6/24]:SkinnyTryCall to 23 instance 1 start at 0 secondary 0
033378: Apr 9 15:28:51.479: ephone-7[6/24][SEP002699EF9CAE]:KeypadButtonMessage 1
033379: Apr 9 15:28:51.479: ephone-7[6/24]:Entering FAC code
033380: Apr 9 15:28:51.479: ephone-7[6/24]:At fac_dial NOMATCHED/NORMAL state
033381: Apr 9 15:28:51.479: ephone-7[6/24]:
033382: Apr 9 15:28:51.479: bulk_sd_search_lists:Entry: digit:1, prefix= # state=7, index= 1
033383: Apr 9 15:28:51.479: ephone-7[6/24][SEP002699EF9CAE]:
033384: Apr 9 15:28:51.479: bulk_sd_search_lists: button= 1 state NOT_IN_SD
033385: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 1 SIEZE
033386: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033387: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 1 SIEZE
033388: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033389: Apr 9 15:28:51.479: ephone-7[6/24][SEP002699EF9CAE]:Store ReDial digit: 231
033390: Apr 9 15:28:51.479: ephone-7[6/24]:SkinnyTryCall to 231 instance 1 start at 0 secondary 0
SkinnyTryCall to 231 instance 1 match DN 13
033391: Apr 9 15:28:51.479: SkinnyGetCallState for DN 13 chan 1 IDLE
033392: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033393: Apr 9 15:28:51.479: ephone-7[6/24]:Skinny-to-Skinny call DN 11 chan 1 to DN 13 chan 1 instance 1
033394: Apr 9 15:28:51.479: ephone-7[6/24]:UpdateCallState DN 11 chan 1 state 1 calleddn 13 chan 1
033395: Apr 9 15:28:51.479: ephone-7[6/24]:Binding ephone-7 to DN 11 chan 1 s2s:0
033396: Apr 9 15:28:51.479: Binding calledDn 13 chan 1 to DN 11 chan 1
033397: Apr 9 15:28:51.479: ephone-7[6/24]:Block FAC when call at ALERTING
033398: Apr 9 15:28:51.479: Skinny Call State change for DN 11 chan 1 ALERTING from SIEZE
033399: Apr 9 15:28:51.479: ephone-(7) DN 11 chan 1 calledDn 13 chan 1 callingDn -1 chan 1 :: port=0
033400: Apr 9 15:28:51.479: SkinnyUpdateCstate DN 11 chan 1 cstate 3
033401: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 1 ALERTING
033402: Apr 9 15:28:51.479: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033403: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 1 ALERTING
033404: Apr 9 15:28:51.479: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033405: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 2 IDLE
033406: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033407: Apr 9 15:28:51.479: DN 11 chan 1 ephone-1 state set to RemoteMultiline
033408: Apr 9 15:28:51.479: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033409: Apr 9 15:28:51.479: SkinnyGetCallState for DN 39 chan 1 IDLE
033410: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033411: Apr 9 15:28:51.479: SkinnyGetCallState for DN 39 chan 2 IDLE
033412: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033413: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 1 ALERTING
033414: Apr 9 15:28:51.479: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033415: Apr 9 15:28:51.479: SkinnyGetCallState for DN 11 chan 2 IDLE
033416: Apr 9 15:28:51.479: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033417: Apr 9 15:28:51.479: DN 11 chan 1 ephone-5 state set to RemoteMultiline
033418: Apr 9 15:28:51.479: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033419: Apr 9 15:28:51.479: ephone-7[6/24][SEP002699EF9CAE]:UpdateCState select phone for DN 11 instance 3
033420: Apr 9 15:28:51.479: ephone-7[6/24]:SkinnyUpdateCState activeLine 1 chan 1 DN 11 ref 1353
033421: Apr 9 15:28:51.479: ephone-7[6/24][SEP002699EF9CAE]:Send TsProceed for TsRingOut DN 11 line 1 chan 1
033422: Apr 9 15:28:51.479: ephone-7[6/24]:DialedNumber: 231 DN 11 line 1 ref 1353
033423: Apr 9 15:28:51.479: ephone-7[24]:SetCallState line 1 DN 11(-1) chan 1 ref 1353 TsProceed
033424: Apr 9 15:28:51.483: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033425: Apr 9 15:28:51.483: ephone-7[6/24]:SkinnyTrackActiveCall for line 1 ref 1353 state 12 (slot 0)
033426: Apr 9 15:28:51.483: ephone-7[24]:SetCallState line 1 DN 11(-1) chan 1 ref 1353 TsRingOut
033427: Apr 9 15:28:51.483: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033428: Apr 9 15:28:51.483: ephone-7[6/24]:SkinnyTrackActiveCall for line 1 ref 1353 state 3 (slot 0)
033429: Apr 9 15:28:51.483: ephone-7[6/24]:CallPrompt line 1 ref 1353:tag 122 (Ring Out)
033430: Apr 9 15:28:51.483: ephone-7[6/24]:SelectPhoneSoftKeys set 8 mask FFFF for line 1 ref 1353
033431: Apr 9 15:28:51.483: SkinnyGetCallState for DN 11 chan 1 ALERTING
033432: Apr 9 15:28:51.483: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033433: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033434: Apr 9 15:28:51.483: SkinnySetCallInfoName calling dn 11 chan 1 dn 11 chan 1,calling [237] called [231] calling name Alain Richard called name JeanMichel Terrat
033435: Apr 9 15:28:51.483: SetCallInfo DN 11 chan 1 is not skinny-to-skinny
033436: Apr 9 15:28:51.483: SkinnyGetCallState for DN 11 chan 1 ALERTING
033437: Apr 9 15:28:51.483: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033438: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo outgoing call line 1 ref 1353
033439: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo callingNumber=237
033440: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo calledNumber=231
033441: Apr 9 15:28:51.483: ephone-7[24]::callingNumber 237
033442: Apr 9 15:28:51.483: ephone-7[24]::callingParty 237
033443: Apr 9 15:28:51.483: ephone-7[6/24]:Call Info DN 11 line 1 ref 1353 call state 1 called 231 calling 237 origcalled
033444: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:
033445: Apr 9 15:28:51.483: bulk_speeddial_update_callinfo: 6
033446: Apr 9 15:28:51.483: ephone-7[6/24]:Call Info DN 11 line 1 ref 1353 called 231 calling 237 alternateCalling 237 origcalled 231 calltype 2
033447: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:Call Info for chan 1
033448: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:Original Called Name JeanMichel Terrat
033449: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo callingName=Alain Richard
033450: Apr 9 15:28:51.483: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo calledName=JeanMichel Terrat
peer_vdb is NULL for DN 11, chan 1 at SkinnyIsPeerNonSCCP
033451: Apr 9 15:28:51.495: SkinnyUpdateDnState by EFXS_PROCEEDING
for DN 11 chan 1 to state ALERTING
033452: Apr 9 15:28:51.495: ephone-7[6/24]:UpdateCallState DN 11 chan 1 state 1 calleddn 13 chan 1
033453: Apr 9 15:28:51.495: ephone-7[6/24]:Binding ephone-7 to DN 11 chan 1 s2s:0
033454: Apr 9 15:28:51.495: Binding calledDn 13 chan 1 to DN 11 chan 1
033455: Apr 9 15:28:51.495: ephone-7[6/24]:Block FAC when call at ALERTING
033456: Apr 9 15:28:51.495: Skinny Call State change for DN 11 chan 1 ALERTING from ALERTING
033457: Apr 9 15:28:51.495: ephone-(7) DN 11 chan 1 calledDn 13 chan 1 callingDn -1 chan 1 :: port=0
033458: Apr 9 15:28:51.495: SkinnyGetCallState for DN 11 chan 1 ALERTING
033459: Apr 9 15:28:51.499: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033460: Apr 9 15:28:51.499: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033461: Apr 9 15:28:51.499: SkinnyTransfereeHairpinRinging: dn 11 chan 1 tonetype 35
033462: Apr 9 15:28:51.499: dn_tone_control DN=11 chan 1 tonetype=35:DtLineBusyTone onoff=1 pid=284
033463: Apr 9 15:28:51.499: SkinnyGetCallState for DN 11 chan 1 ALERTING
033464: Apr 9 15:28:51.499: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033465: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:SkinnyDisplayCallInfo outgoing call line 1 ref 1353
033466: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:Discard duplicate SkinnyDisplayCallInfo for ref 1353
033467: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:DN 11 disc reason 17 user busy state ALERTING
033468: Apr 9 15:28:51.503: SkinnyUpdateDnState by Busy during TsRingout
for DN 11 chan 1 to state BUSY
033469: Apr 9 15:28:51.503: ephone-7[6/24]:UpdateCallState DN 11 chan 1 state 6 calleddn 13 chan 1
033470: Apr 9 15:28:51.503: ephone-7[6/24]:Binding ephone-7 to DN 11 chan 1 s2s:0
033471: Apr 9 15:28:51.503: Binding calledDn 13 chan 1 to DN 11 chan 1
033472: Apr 9 15:28:51.503: Skinny Call State change for DN 11 chan 1 BUSY from ALERTING
033473: Apr 9 15:28:51.503: ephone-(7) DN 11 chan 1 calledDn 13 chan 1 callingDn -1 chan 1 :: port=0
033474: Apr 9 15:28:51.503: SkinnyUpdateCstate DN 11 chan 1 cstate 6
033475: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033476: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033477: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033478: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033479: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 2 IDLE
033480: Apr 9 15:28:51.503: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033481: Apr 9 15:28:51.503: DN 11 chan 1 ephone-1 state set to RemoteMultiline
033482: Apr 9 15:28:51.503: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033483: Apr 9 15:28:51.503: SkinnyGetCallState for DN 39 chan 1 IDLE
033484: Apr 9 15:28:51.503: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033485: Apr 9 15:28:51.503: SkinnyGetCallState for DN 39 chan 2 IDLE
033486: Apr 9 15:28:51.503: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033487: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033488: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033489: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 2 IDLE
033490: Apr 9 15:28:51.503: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033491: Apr 9 15:28:51.503: DN 11 chan 1 ephone-5 state set to RemoteMultiline
033492: Apr 9 15:28:51.503: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033493: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:UpdateCState select phone for DN 11 instance 3
033494: Apr 9 15:28:51.503: ephone-7[6/24]:SkinnyUpdateCState activeLine 1 chan 1 DN 11 ref 1353
033495: Apr 9 15:28:51.503: ephone-7[24]:SetCallState line 1 DN 11(-1) chan 1 ref 1353 TsBusy
033496: Apr 9 15:28:51.503: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033497: Apr 9 15:28:51.503: ephone-7[6/24]:SkinnyTrackActiveCall for line 1 ref 1353 state 6 (slot 0)
033498: Apr 9 15:28:51.503: ephone-7[6/24]:CallPrompt line 1 ref 1353:tag 125 (Busy)
033499: Apr 9 15:28:51.503: ephone-7[6/24]:SelectPhoneSoftKeys set 4 mask FFFF for line 1 ref 1353
033500: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033501: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033502: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033503: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033504: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033505: Apr 9 15:28:51.503: SkinnyGetCallState for DN 11 chan 1 BUSY
033506: Apr 9 15:28:51.503: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033507: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:is_auto_local 1 for DN 11
033508: Apr 9 15:28:51.503: ephone-7[6/24][SEP002699EF9CAE]:SkinnySetToneRef callRef 0x549 tone 0x23
033509: Apr 9 15:28:51.503: ephone-7[6/24]:SkinnyPhoneTone: StartTone sent: normal line=1 ref=1353 tone=0x23
033510: Apr 9 15:28:51.503: Skinny StartTone 35 sent on ephone socket [24] DtLineBusyTone
033511: Apr 9 15:28:53.123: ephone-7[6/24][SEP002699EF9CAE]:SoftKeyEventMessage event 9 line 1 callref 1353
033512: Apr 9 15:28:53.123: ephone-7[6/24]:Block FAC when Sk pressed.
033513: Apr 9 15:28:53.123: ephone-7[6/24][SEP002699EF9CAE]:SK ENDCALL line 1 ref 1353
033514: Apr 9 15:28:53.127: ephone-7[6/24]:ONHOOK (internal)
033515: Apr 9 15:28:53.127: ephone-7[6/24]:fStationOnHookMessage: sys normal line=1 ch=1
033516: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:ClearCallPrompt line 1 ref 1353
033517: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:
033518: Apr 9 15:28:53.127: bulk_speeddial_init_ephone: 6
033519: Apr 9 15:28:53.127: ephone-7[6/24]:Line 1 chan 1 refresh (DN 11 state=6)
033520: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:Check for transfer commit line 1 chan 1
033521: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:Clean-up transferor_dn -1 consult_dn -1
033522: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:Set FAC enabled (1) and dial mode (0)
033523: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 1 BUSY
033524: Apr 9 15:28:53.127: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033525: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:Onhook clean up for DN 11 chan 1 in state 6
033526: Apr 9 15:28:53.127: ephone-7[6/24]:UpdateCallState DN 11 chan 1 state 0 calleddn -1 chan 1
033527: Apr 9 15:28:53.127: ephone-7[6/24]:Binding ephone-7 to DN 11 chan 1 s2s:0
033528: Apr 9 15:28:53.127: ephone-7[6/24][SEP002699EF9CAE]:Set FAC enabled (1) and dial mode (0)
033529: Apr 9 15:28:53.127: DN 11 chan 1 End Voice_Mode
033530: Apr 9 15:28:53.127: SkinnySetDnInvokeId DN 11 chan 1 id 0 set=0
033531: Apr 9 15:28:53.127: SkinnyStopDnRecallTimer: dn 11 chan 1
033532: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 1 IDLE
033533: Apr 9 15:28:53.127: called DN 13 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033534: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 2 IDLE
033535: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033536: Apr 9 15:28:53.127: SkinnySetCallInfoName calling dn -1 chan 1 dn 11 chan 1,calling [] called []
033537: Apr 9 15:28:53.127: SetCallInfo DN 11 chan 1 is not skinny-to-skinny
033538: Apr 9 15:28:53.127: Skinny Call State change for DN 11 chan 1 IDLE from BUSY
033539: Apr 9 15:28:53.127: ephone-(7) DN 11 chan 1 calledDn -1 chan 1 callingDn -1 chan 1 :: port=0
033540: Apr 9 15:28:53.127: SkinnyUpdateCstate DN 11 chan 1 cstate 2
033541: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 1 IDLE
033542: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033543: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 2 IDLE
033544: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033545: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 1 IDLE
033546: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033547: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 2 IDLE
033548: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033549: Apr 9 15:28:53.127: DN 11 chan 1 ephone-1 state set to 2
033550: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 1 IDLE
033551: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033552: Apr 9 15:28:53.127: SkinnyGetCallState for DN 11 chan 2 IDLE
033553: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033554: Apr 9 15:28:53.127: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033555: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 1 IDLE
033556: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033557: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 2 IDLE
033558: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033559: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 1 IDLE
033560: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033561: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 2 IDLE
033562: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033563: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 1 IDLE
033564: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033565: Apr 9 15:28:53.127: SkinnyGetCallState for DN 39 chan 2 IDLE
033566: Apr 9 15:28:53.127: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033567: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 1 IDLE
033568: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033569: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033570: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033571: Apr 9 15:28:53.131: SkinnyGetCallState for DN 13 chan 1 IDLE
033572: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033573: Apr 9 15:28:53.131: SkinnyGetCallState for DN 13 chan 2 IDLE
033574: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033575: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033576: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033577: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 1 IDLE
033578: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033579: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033580: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033581: Apr 9 15:28:53.131: DN 11 chan 1 ephone-5 state set to 2
033582: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 1 IDLE
033583: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033584: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033585: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033586: Apr 9 15:28:53.131: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033587: Apr 9 15:28:53.131: SkinnyGetCallState for DN 39 chan 1 IDLE
033588: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033589: Apr 9 15:28:53.131: SkinnyGetCallState for DN 39 chan 2 IDLE
033590: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033591: Apr 9 15:28:53.131: SkinnyGetCallState for DN 13 chan 1 IDLE
033592: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033593: Apr 9 15:28:53.131: SkinnyGetCallState for DN 13 chan 2 IDLE
033594: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033595: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 1 IDLE
033596: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033597: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033598: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033599: Apr 9 15:28:53.131: ephone-7[6/24][SEP002699EF9CAE]:UpdateCState select phone for DN 11 instance 3
033600: Apr 9 15:28:53.131: ephone-7[6/24]:SkinnyUpdateCState activeLine 1 chan 1 DN 11 ref 1353
033601: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 1 IDLE
033602: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033603: Apr 9 15:28:53.131: SkinnyGetCallState for DN 11 chan 2 IDLE
033604: Apr 9 15:28:53.131: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033605: Apr 9 15:28:53.131: ephone-7[24]:SetCallState line 1 DN 11(-1) chan 1 ref 1353 TsOnHook
033606: Apr 9 15:28:53.131: ephone_get_callid_from_dn_chan: dn[11] chan[1] callID[1977]
033607: Apr 9 15:28:53.131: ephone-7[6/24]:SkinnyTrackActiveCall for line 1 ref 1353 state 2 (slot 0)
033608: Apr 9 15:28:53.131: ephone-7[6/24][SEP002699EF9CAE]:ClearCallPrompt line 1 ref 1353
033609: Apr 9 15:28:53.135: ephone-7[6/24]:SelectPhoneSoftKeys set 0 mask FF7F for line 1 ref 1353
033610: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:ClearCallPrompt line 0 ref 0
033611: Apr 9 15:28:53.135: ephone-7[6/24]:SelectPhoneSoftKeys set 0 mask FF7F for line 0 ref 0
033612: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 1 IDLE
033613: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033614: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 2 IDLE
033615: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033616: Apr 9 15:28:53.135: ephone-7[6/24]:Clean Up Speakerphone state
033617: Apr 9 15:28:53.135: ephone-7[6/24]:SpeakerPhoneOnHook
033618: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:Clean up activeline 1
033619: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyGetToneRef toneRef 0x549 callRef 0x549
033620: Apr 9 15:28:53.135: ephone-7[6/24]:SkinnyPhoneToneDirect: StopTone sent: normal line=1 ref=1353 tone=0x0
033621: Apr 9 15:28:53.135: Skinny StopTone sent on ephone socket [24]
033622: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 1 IDLE
033623: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033624: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 2 IDLE
033625: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033626: Apr 9 15:28:53.135: SkinnyGetCallState for DN 39 chan 1 IDLE
033627: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033628: Apr 9 15:28:53.135: SkinnyGetCallState for DN 39 chan 2 IDLE
033629: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033630: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyGetHiddenRingingChan: phone 6 dn 11 chan 1
033631: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 2 IDLE
033632: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033633: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 1 IDLE
033634: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033635: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033636: Apr 9 15:28:53.135: UnBinding ephone-7 from DN 11 chan 1
033637: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyArmPhoneCallbacks scan 2 lines
033638: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyArmPhoneCallbacks for 4 targets
033639: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyCheckPendingCallBackPhone scan 2 lines
033640: Apr 9 15:28:53.135: ephone-7[6/24]:---SkinnySyncPhoneDnOverlays is onhook
033641: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 1 IDLE
033642: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033643: Apr 9 15:28:53.135: SkinnyGetCallState for DN 11 chan 2 IDLE
033644: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033645: Apr 9 15:28:53.135: SkinnyGetCallState for DN 39 chan 1 IDLE
033646: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033647: Apr 9 15:28:53.135: SkinnyGetCallState for DN 39 chan 2 IDLE
033648: Apr 9 15:28:53.135: called DN -1 chan 1, calling DN -1 chan 1 phone -1 incoming s2s:0
033649: Apr 9 15:28:53.135: ephone-7[6/24]:SpeakerPhoneOnHook
033650: Apr 9 15:28:53.135: ephone-7[6/24]:Speaker is not on, SpeakerPhoneOnHook suppressed
033651: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:ClearCallPrompt line 1 ref 1353
033652: Apr 9 15:28:53.135: ephone-7[6/24]:SelectPhoneSoftKeys set 0 mask FF7F for line 1 ref 1353
033653: Apr 9 15:28:53.135: ephone-7[6/24][SEP002699EF9CAE]:SkinnyCheckPendingCallBackPhone scan 2 lines
033654: Apr 9 15:28:53.147: SkinnyGetCallState for DN 11 chan 1 IDLE
033655: Apr 9 15:28:53.151: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
033656: Apr 9 15:28:53.151: ephone-7[6/24]:SkinnyConfirmOnHookAck: dn 11 chan 1 dn_index 11 phone=6, pickupOnHook=0
033657: Apr 9 15:28:53.151: ephone-7[6/24][SEP002699EF9CAE]:SkinnyCheckPendingCallBackPhone scan 2 lines
033658: Apr 9 15:28:53.155: dn_tone_control DN=11 chan 1 tonetype=0:DtSilence onoff=0 pid=284
033659: Apr 9 15:28:53.155: SkinnyGetCallState for DN 11 chan 1 IDLE
033660: Apr 9 15:28:53.155: called DN -1 chan 1, calling DN -1 chan 1 phone -1 s2s:0
The interesting part is from 033459 to 033462 :
033459: Apr 9 15:28:51.499: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
033460: Apr 9 15:28:51.499: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
033461: Apr 9 15:28:51.499: SkinnyTransfereeHairpinRinging: dn 11 chan 1 tonetype 35
033462: Apr 9 15:28:51.499: dn_tone_control DN=11 chan 1 tonetype=35:DtLineBusyTone onoff=1 pid=284
we see here that dn 11 (the caller) receive immedialty a busy tone (tonetype=35:DtLineBusyTone) and there is no line about the called phone.
On calls that succeed to ring the called phone, the lines are replaced by :
038035: Apr 9 15:57:27.838: called DN 13 chan 1, calling DN -1 chan 1 phone 7 s2s:0
038036: Apr 9 15:57:27.838: ephone-7[6/24][SEP002699EF9CAE]:SetLineLamp ignored for telecaster phones with 2 lines
038037: Apr 9 15:57:27.850: ephone-8[7/15]:video_caps_count is zero
038038: Apr 9 15:57:27.854: SkinnySetCallInfoName calling dn 11 chan 1 dn 13 chan 1,calling [237] called [231] calling name Alain Richard
038039: Apr 9 15:57:27.854: SetCallInfo DN 13 chan 1 is not skinny-to-skinny
038040: Apr 9 15:57:27.854: Binding callingDn 11 chan 1 to DN 13 chan 1 at SetCallInfo
038041: Apr 9 15:57:27.854: Skinny-to-Skinny Call DN 11 chan 1 to DN 13 chan 1
038042: Apr 9 15:57:27.854: SkinnyGetCallState for DN 13 chan 1 IDLE
038043: Apr 9 15:57:27.854: called DN -1 chan 1, calling DN 11 chan 1 phone -1 s2s:1
038044: Apr 9 15:57:27.854: SkinnyUpdateDnState by EFXS_RING_GENERATE
for DN 13 chan 1 to state RINGING
038045: Apr 9 15:57:27.854: ephone-8[7/15]:UpdateCallState DN 13 chan 1 state 7 calleddn -1 chan 1
038046: Apr 9 15:57:27.854: ephone-8[7/15]:Binding ephone-8 to DN 13 chan 1 s2s:1
038047: Apr 9 15:57:27.854: Assign Call Ref 1374 to DN 13 chan 1
038048: Apr 9 15:57:27.854: Skinny Call State change for DN 13 chan 1 RINGING from IDLE
038049: Apr 9 15:57:27.854: ephone-(8) DN 13 chan 1 calledDn -1 chan 1 callingDn 11 chan 1 :: port=0 incoming
038050: Apr 9 15:57:27.854: SkinnyUpdateCstate DN 13 chan 1 cstate 4
038051: Apr 9 15:57:27.854: SkinnyGetCallState for DN 13 chan 1 RINGING
038052: Apr 9 15:57:27.854: called DN -1 chan 1, calling DN 11 chan 1 phone -1 incoming s2s:1
038053: Apr 9 15:57:27.854: SkinnyGetCallState for DN 13 chan 1 RINGING
here we see that there is debugging lines for the called phone (ephone-8).
As the issue is very random (about 20% of time, with this phone and some other), I have no idea about where to look at.
Do you have any idea about other debuging flags I may try to see why some calls are not presented to the destination phone ?
--
Alain RICHARD <mailto:alain.richard at equation.fr>
EQUATION SA <http://www.equation.fr/>
Tel : +33 477 79 48 00 Fax : +33 477 79 48 01
E-Liance, Opérateur des entreprises et collectivités,
Liaisons Fibre optique, SDSL et ADSL <http://www.e-liance.fr>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20100409/149ae14f/attachment.html>
More information about the cisco-voip
mailing list