Problems with on hook phones

[dspaan]

We migrated vicidial to another server and since them we are having problems with on hook calls.

The phone rings but when you press the button to answer the call it just drops and you have to wait for the 2nd time or 3rd time to ring and then you answer it. We have set agent on hook ring time in the ingroup to 60 seconds but that doesn't help. The phones we are using are Yealink. This doesn't happen on softphones. Before it worked fine on both types. The older server was Asterisk 1.8, could this be an Asterisk/Yealink/Vicidial specific issue?

How can we find out what is causing this?

[mflorell]

What does the Asterisk CLI output(with AGI Output set to BOTH) look like when this happens? Also, what does it look like when it works fine using a softphone?

[dspaan]

This is what i see when i answer with a Yealink phone:

[Jun 27 08:19:17] -- Executing [077*073*228*248*475@default:1] Goto("Local/077*073*228*248*475@default-00000073;2", "default,475,1") in new stack
[Jun 27 08:19:17] -- Goto (default,475,1)
[Jun 27 08:19:17] -- Executing [475@default:1] Dial("Local/077*073*228*248*475@default-00000073;2", "SIP/475,60,") in new stack
[Jun 27 08:19:17] == Using SIP RTP CoS mark 5
[Jun 27 08:19:17] -- Called SIP/475
[Jun 27 08:19:17] -- SIP/475-000001cf is ringing
[Jun 27 08:19:18] -- Started music on hold, class 'telforce', on SIP/motto.nl-000001ce
[Jun 27 08:19:19] > 0x7f6a800148d0 -- Strict RTP learning after remote address set to: 192.168.4.25:11784
[Jun 27 08:19:19] -- SIP/475-000001cf answered Local/077*073*228*248*475@default-00000073;2
[Jun 27 08:19:19] > Channel Local/077*073*228*248*475@default-00000073;1 was answered
[Jun 27 08:19:19] -- Executing [8331*32*Y6270819110000345702*1004*475@default:1] Playback("Local/077*073*228*248*475@default-00000073;1", "sip-silence") in new stack
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (language 'en')
[Jun 27 08:19:19] -- Executing [8331*32*Y6270819110000345702*1004*475@default:2] AGI("Local/077*073*228*248*475@default-00000073;1", "agi-VDAD_RINGALL.agi,8331*32*Y6270819110000345702*1004*475") in new stack
[Jun 27 08:19:19] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:19:19] -- Executing [8331*32*Y6270819110000345702*1004*475@default:3] AGI("Local/077*073*228*248*475@default-00000073;1", "agi-VDAD_RINGALL.agi,8331*32*Y6270819110000345702*1004*475") in new stack
[Jun 27 08:19:19] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:19:19] -- Executing [8331*32*Y6270819110000345702*1004*475@default:4] AGI("Local/077*073*228*248*475@default-00000073;1", "agi-VDAD_RINGALL.agi,8331*32*Y6270819110000345702*1004*475") in new stack
[Jun 27 08:19:19] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] > 0x7f6a800148d0 -- Strict RTP switching source address to 82.95.238.35:11784
[Jun 27 08:19:19] -- Executing [h@default:1] AGI("Local/077*073*228*248*475@default-00000073;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----2-----0") in new stack
[Jun 27 08:19:19] -- <Local/077*073*228*248*475@default-00000073;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---2-----0 completed, returning 0
[Jun 27 08:19:19] == Spawn extension (default, 475, 1) exited non-zero on 'Local/077*073*228*248*475@default-00000073;2'
[Jun 27 08:19:19] -- <SIP/475-000001cf> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <SIP/475-000001cf> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:19:19] -- <SIP/475-000001cf>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:19:19] -- Executing [8331*32*Y6270819110000345702*1004*475@default:5] Hangup("SIP/475-000001cf", "") in new stack
[Jun 27 08:19:19] == Spawn extension (default, 8331*32*Y6270819110000345702*1004*475, 5) exited non-zero on 'SIP/475-000001cf'
[Jun 27 08:19:19] -- Executing [h@default:1] AGI("SIP/475-000001cf", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Jun 27 08:19:19] -- <SIP/475-000001cf>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0

This is what i see when i answer with a softphone:

[Jun 27 08:25:04] -- Executing [077*073*228*248*258@default:1] Goto("Local/077*073*228*248*258@default-00000076;2", "default,258,1") in new stack
[Jun 27 08:25:04] -- Goto (default,258,1)
[Jun 27 08:25:04] -- Executing [258@default:1] Dial("Local/077*073*228*248*258@default-00000076;2", "SIP/258,60,") in new stack
[Jun 27 08:25:04] == Using SIP RTP CoS mark 5
[Jun 27 08:25:04] -- Called SIP/258
[Jun 27 08:25:04] -- SIP/258-000001d1 is ringing
[Jun 27 08:25:06] -- Started music on hold, class 'telforce', on SIP/motto.nl-000001d0
[Jun 27 08:25:07] > 0x7f6b040148c0 -- Strict RTP learning after remote address set to: 192.168.4.70:40024
[Jun 27 08:25:07] -- SIP/258-000001d1 answered Local/077*073*228*248*258@default-00000076;2
[Jun 27 08:25:07] > Channel Local/077*073*228*248*258@default-00000076;1 was answered
[Jun 27 08:25:07] -- Executing [8331*33*Y6270824580000227731*1004*258@default:1] Playback("Local/077*073*228*248*258@default-00000076;1", "sip-silence") in new stack
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;1> Playing 'sip-silence.gsm' (language 'en')
[Jun 27 08:25:07] -- Executing [8331*33*Y6270824580000227731*1004*258@default:2] AGI("Local/077*073*228*248*258@default-00000076;1", "agi-VDAD_RINGALL.agi,8331*33*Y6270824580000227731*1004*258") in new stack
[Jun 27 08:25:07] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;1>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:25:07] -- Executing [8331*33*Y6270824580000227731*1004*258@default:3] AGI("Local/077*073*228*248*258@default-00000076;1", "agi-VDAD_RINGALL.agi,8331*33*Y6270824580000227731*1004*258") in new stack
[Jun 27 08:25:07] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:25:07] > 0x7f6b040148c0 -- Strict RTP switching source address to 82.95.238.35:40024
[Jun 27 08:25:07] -- Executing [h@default:1] AGI("Local/077*073*228*248*258@default-00000076;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----3-----0") in new stack
[Jun 27 08:25:07] -- <Local/077*073*228*248*258@default-00000076;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---3-----0 completed, returning 0
[Jun 27 08:25:07] == Spawn extension (default, 258, 1) exited non-zero on 'Local/077*073*228*248*258@default-00000076;2'
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:25:07] -- Executing [8331*33*Y6270824580000227731*1004*258@default:4] AGI("SIP/258-000001d1", "agi-VDAD_RINGALL.agi,8331*33*Y6270824580000227731*1004*258") in new stack
[Jun 27 08:25:07] -- Launched AGI Script /usr/share/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Jun 27 08:25:07] -- AGI Script Executing Application: (Monitor) Options: (wav,/var/spool/asterisk/monitor/MIX/20180627-082507_31620243061_1004_227731)
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:07] -- <SIP/258-000001d1> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/258-000001d1>AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Jun 27 08:25:08] -- Executing [077*073*228*248*78600051@default:1] Goto("SIP/258-000001d1", "default,78600051,1") in new stack
[Jun 27 08:25:08] -- Goto (default,78600051,1)
[Jun 27 08:25:08] -- Executing [78600051@default:1] MeetMe("SIP/258-000001d1", "8600051,Fq") in new stack
[Jun 27 08:25:08] == Parsing '/etc/asterisk/meetme.conf': Found
[Jun 27 08:25:08] == Parsing '/etc/asterisk/meetme-vicidial.conf': Found
[Jun 27 08:25:08] -- Created MeetMe conference 1023 for conference '8600051'
[Jun 27 08:25:08] -- Stopped music on hold on SIP/motto.nl-000001d0
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0> Playing 'sip-silence.gsm' (escape_digits=) (sample_offset 0) (language 'en')
[Jun 27 08:25:08] -- <SIP/motto.nl-000001d0>AGI Script agi-VDAD_ALL_inbound.agi completed, returning 0
[Jun 27 08:25:08] -- Executing [077*073*228*248*8600051@default:1] Goto("SIP/motto.nl-000001d0", "default,8600051,1") in new stack
[Jun 27 08:25:08] -- Goto (default,8600051,1)
[Jun 27 08:25:08] -- Executing [8600051@default:1] MeetMe("SIP/motto.nl-000001d0", "8600051,F") in new stack
[Jun 27 08:25:09] > 0x7f6b040148c0 -- Strict RTP learning complete - Locking on source address 82.95.238.35:40024

[mflorell]

You don't have AGI output set to BOTH on these examples.

The issue is probably that your hardphones aren't sending audio yet so they can't be resolved. We've had to add up to 20 additional "agi-VDAD_RINGALL.agi" entries in the dialplan to fix this issue for clients in the past.

[dspaan]

Hi Matt, can you give an example of such a line? Do i add this in the carrier dialplan?

[mflorell]

from the extensions.conf file:

; these are used for the ring_all function in VICIDIAL
exten => _8331*.,1,Playback(sip-silence)
exten => _8331*.,n,AGI(agi-VDAD_RINGALL.agi,${EXTEN})
exten => _8331*.,n,AGI(agi-VDAD_RINGALL.agi,${EXTEN})
exten => _8331*.,n,AGI(agi-VDAD_RINGALL.agi,${EXTEN})
exten => _8331*.,n,Hangup()


You need to try adding more of the AGI entries

[dspaan]

Thanks Matt, it's working!

[mflorell]

Thanks for the postback