Call comes to agent from SIP-trunk DID and answered in the same server:
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Executing [XXXXXXXX3302@trunkinbound:1] AGI("SIP/TPO_SIP-00001780", "agi-DID_route.agi") in new stack
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-DID_route.agi
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- AGI Script agi-DID_route.agi completed, returning 0
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Executing [99909*9***DID@default:1] Answer("SIP/TPO_SIP-00001780", "") in new stack
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Executing [99909*9***DID@default:2] AGI("SIP/TPO_SIP-00001780", "agi-VDAD_ALL_inbound.agi") in new stack
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_inbound.agi
[Feb 1 14:43:39] VERBOSE[3857] logger.c: -- Playing 'sip-silence' (escape_digits=) (sample_offset 0)
[Feb 1 14:43:41] VERBOSE[3857] logger.c: -- Started music on hold, class 'moh_prompt', on SIP/TPO_SIP-00001780
[Feb 1 14:43:46] VERBOSE[3875] logger.c: -- Executing [192*168*XX*XX*5000@default:1] Goto("Local/192*168*XX*061*5000@default-8fa7,2", "default|5000|1") in new stack
[Feb 1 14:43:46] VERBOSE[3875] logger.c: -- Goto (default,5000,1)
[Feb 1 14:43:46] VERBOSE[3875] logger.c: -- Executing [5000@default:1] Dial("Local/192*168*XX*XX*5000@default-8fa7,2", "SIP/5000|60|") in new stack
[Feb 1 14:43:46] VERBOSE[3875] logger.c: -- Called 5000
[Feb 1 14:43:46] VERBOSE[3875] logger.c: -- SIP/5000-00001781 is ringing
[Feb 1 14:43:47] VERBOSE[3875] logger.c: -- SIP/5000-00001781 answered Local/192*168*XX*XX*5000@default-8fa7,2
[Feb 1 14:43:47] VERBOSE[3874] logger.c: > Channel Local/192*168*XX*XX*5000@default-8fa7,1 was answered.
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [8331*99363*Y2011443390000099384*101*5000@default:1] Playback("Local/192*168*XX*XX*5000@default-8fa7,1", "sip-silence") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- <Local/192*168*XX*XX*5000@default-8fa7,1> Playing 'sip-silence' (language 'en')
[Feb 1 14:43:47] WARNING[3877] file.c: Unexpected control subclass '-1'
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [8331*99363*Y2011443390000099384*101*5000@default:2] AGI("Local/192*168*XX*XX*5000@default-8fa7,1", "agi-VDAD_RINGALL.agi|8331*99363*Y2011443390000099384*101*5000") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [8331*99363*Y2011443390000099384*101*5000@default:3] AGI("Local/192*168*XX*XX*5000@default-8fa7,1", "agi-VDAD_RINGALL.agi|8331*99363*Y2011443390000099384*101*5000") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [8331*99363*Y2011443390000099384*101*5000@default:3] AGI("Local/192*168*XX*XX*5000@default-8fa7,1", "agi-VDAD_RINGALL.agi|8331*99363*Y2011443390000099384*101*5000") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Feb 1 14:43:47] VERBOSE[3875] logger.c: -- Executing [h@default:1] DeadAGI("Local/192*168*XX*XX*5000@default-8fa7,2", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----1-----0") in new stack
[Feb 1 14:43:47] VERBOSE[3875] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----1-----0 completed, returning 0
[Feb 1 14:43:47] VERBOSE[3875] logger.c: == Spawn extension (default, 5000, 1) exited non-zero on 'Local/192*168*XX*XX*5000@default-8fa7,2'
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [8331*99363*Y2011443390000099384*101*5000@default:4] AGI("SIP/5000-00001781", "agi-VDAD_RINGALL.agi|8331*99363*Y2011443390000099384*101*5000") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_RINGALL.agi
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- AGI Script agi-VDAD_RINGALL.agi completed, returning 0
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [192*168*XX*XX*78600052@default:1] Goto("SIP/5000-00001781", "default|78600052|1") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Goto (default,78600052,1)
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Executing [78600052@default:1] MeetMe("SIP/5000-00001781", "8600052|Fq") in new stack
[Feb 1 14:43:47] VERBOSE[3877] logger.c: -- Created MeetMe conference 1023 for conference '8600052'
[Feb 1 14:43:48] VERBOSE[3891] logger.c: -- Executing [192*168*XX*XX*78600052@default:1] Goto("Local/192*168*XX*XX*78600052@default-f9f1,2", "default|78600052|1") in new stack
[Feb 1 14:43:48] VERBOSE[3891] logger.c: -- Goto (default,78600052,1)
[Feb 1 14:43:48] VERBOSE[3891] logger.c: -- Executing [78600052@default:1] MeetMe("Local/192*168*XX*XX*78600052@default-f9f1,2", "8600052|Fq") in new stack
[Feb 1 14:43:48] VERBOSE[3890] logger.c: > Channel Local/192*168*XX*XX*78600052@default-f9f1,1 was answered.
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- Executing [83047777777777@vicidial-auto:1] Answer("Local/192*168*XX*XX*78600052@default-f9f1,1", "") in new stack
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- Executing [83047777777777@vicidial-auto:2] Playback("Local/192*168*XX*XX*78600052@default-f9f1,1", "ding") in new stack
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- <Local/192*168*XX*XX*78600052@default-f9f1,1> Playing 'ding' (language 'en')
[Feb 1 14:43:48] WARNING[3892] file.c: Unexpected control subclass '-1'
[Feb 1 14:43:48] WARNING[3892] file.c: Unexpected control subclass '-1'
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- Executing [83047777777777@vicidial-auto:3] Hangup("Local/192*168*XX*XX*78600052@default-f9f1,1", "") in new stack
[Feb 1 14:43:48] VERBOSE[3892] logger.c: == Spawn extension (vicidial-auto, 83047777777777, 3) exited non-zero on 'Local/192*168*XX*XX*78600052@default-f9f1,1'
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- Executing [h@vicidial-auto:1] DeadAGI("Local/192*168*XX*XX*78600052@default-f9f1,1", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Feb 1 14:43:48] VERBOSE[3892] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0
[Feb 1 14:43:48] VERBOSE[3891] logger.c: == Spawn extension (default, 78600052, 1) exited non-zero on 'Local/192*168*XX*XX*78600052@default-f9f1,2'
[Feb 1 14:43:48] VERBOSE[3891] logger.c: -- Executing [h@default:1] DeadAGI("Local/192*168*XX*XX*78600052@default-f9f1,2", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 14:43:48] VERBOSE[3891] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 1 14:43:51] VERBOSE[3857] logger.c: -- Stopped music on hold on SIP/TPO_SIP-00001780
[Feb 1 14:43:51] ERROR[3857] utils.c: write() returned error: Broken pipe
[Feb 1 14:43:51] VERBOSE[3857] logger.c: -- AGI Script agi-VDAD_ALL_inbound.agi completed, returning 0
[Feb 1 14:43:51] VERBOSE[3857] logger.c: -- Executing [192*168*XX*XX*8600052@default:1] Goto("SIP/TPO_SIP-00001780", "default|8600052|1") in new stack
[Feb 1 14:43:51] VERBOSE[3857] logger.c: -- Goto (default,8600052,1)
[Feb 1 14:43:51] VERBOSE[3857] logger.c: -- Executing [8600052@default:1] MeetMe("SIP/TPO_SIP-00001780", "8600052|F") in new stack
[Feb 1 14:43:53] VERBOSE[3906] logger.c: -- Executing [58600052@default:1] MeetMe("Local/58600052@default-a691,2", "8600052|Fmq") in new stack
[Feb 1 14:43:53] VERBOSE[3905] logger.c: > Channel Local/58600052@default-a691,1 was answered.
[Feb 1 14:43:53] VERBOSE[3907] logger.c: -- Executing [8309@default:1] Answer("Local/58600052@default-a691,1", "") in new stack
[Feb 1 14:43:53] VERBOSE[3907] logger.c: -- Executing [8309@default:2] Monitor("Local/58600052@default-a691,1", "wav|20130201-144348_XXXXXXXXXX_TESTI") in new stack
[Feb 1 14:43:53] VERBOSE[3907] logger.c: -- Executing [8309@default:3] Wait("Local/58600052@default-a691,1", "3600") in new stack
Hangup Customer button pressed:
[Feb 1 14:43:57] VERBOSE[3857] logger.c: == Spawn extension (default, 8600052, 1) exited non-zero on 'SIP/TPO_SIP-00001780'
[Feb 1 14:43:57] VERBOSE[3857] logger.c: -- Executing [h@default:1] DeadAGI("SIP/TPO_SIP-00001780", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 14:43:57] VERBOSE[3857] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 1 14:43:57] VERBOSE[3906] logger.c: == Spawn extension (default, 58600052, 1) exited non-zero on 'Local/58600052@default-a691,2'
[Feb 1 14:43:57] VERBOSE[3906] logger.c: -- Executing [h@default:1] DeadAGI("Local/58600052@default-a691,2", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 14:43:57] VERBOSE[3906] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 1 14:43:57] VERBOSE[3907] logger.c: == Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600052@default-a691,1'
[Feb 1 14:43:57] VERBOSE[3907] logger.c: -- Executing [h@default:1] DeadAGI("Local/58600052@default-a691,1", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 14:43:57] VERBOSE[3907] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
Here the call is still open in the SIP-phone
Pressed hangup from hardphone. The call hangs up from the phone.
[Feb 1 14:44:05] VERBOSE[3877] logger.c: -- Hungup 'DAHDI/pseudo-681500520'
[Feb 1 14:44:05] VERBOSE[3877] logger.c: == Spawn extension (default, 78600052, 1) exited non-zero on 'SIP/5000-00001781'
[Feb 1 14:44:05] VERBOSE[3877] logger.c: -- Executing [h@default:1] DeadAGI("SIP/5000-00001781", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 14:44:05] VERBOSE[3877] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
Call comes in from E1-DID from different server through clustering built-in IAX2-trunk:
[Feb 1 15:04:03] VERBOSE[4349] logger.c: -- Accepting AUTHENTICATED call from 192.168.XX.XY:
> requested format = gsm,
> requested prefs = (gsm|ulaw),
> actual format = ulaw,
> host prefs = (ulaw),
> priority = mine
[Feb 1 15:04:03] VERBOSE[6886] logger.c: -- Executing [5000@default:1] Dial("IAX2/vicidial2-10110", "SIP/5000|60|") in new stack
[Feb 1 15:04:03] VERBOSE[6886] logger.c: -- Called 5000
[Feb 1 15:04:03] VERBOSE[6886] logger.c: -- SIP/5000-0000178d is ringing
[Feb 1 15:04:03] VERBOSE[6886] logger.c: -- SIP/5000-0000178d answered IAX2/vicidial2-10110
[Feb 1 15:04:04] VERBOSE[4381] logger.c: -- Accepting AUTHENTICATED call from 192.168.XX.XY:
> requested format = ulaw,
> requested prefs = (ulaw|gsm),
> actual format = ulaw,
> host prefs = (ulaw),
> priority = mine
[Feb 1 15:04:04] VERBOSE[6894] logger.c: -- Executing [78600052@default:1] MeetMe("IAX2/vicidial2-10924", "8600052|Fq") in new stack
[Feb 1 15:04:04] VERBOSE[6894] logger.c: -- Created MeetMe conference 1023 for conference '8600052'
[Feb 1 15:04:04] VERBOSE[6896] logger.c: -- Executing [192*168*014*061*78600052@default:1] Goto("Local/192*168*XX*XX*78600052@default-e957,2", "default|78600052|1") in new stack
[Feb 1 15:04:04] VERBOSE[6896] logger.c: -- Goto (default,78600052,1)
[Feb 1 15:04:04] VERBOSE[6896] logger.c: -- Executing [78600052@default:1] MeetMe("Local/192*168*XX*XX*78600052@default-e957,2", "8600052|Fq") in new stack
[Feb 1 15:04:04] VERBOSE[6895] logger.c: > Channel Local/192*168*XX*XX*78600052@default-e957,1 was answered.
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- Executing [83047777777777@vicidial-auto:1] Answer("Local/192*168*014*061*78600052@default-e957,1", "") in new stack
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- Executing [83047777777777@vicidial-auto:2] Playback("Local/192*168*014*061*78600052@default-e957,1", "ding") in new stack
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- <Local/192*168*014*061*78600052@default-e957,1> Playing 'ding' (language 'en')
[Feb 1 15:04:04] WARNING[6897] file.c: Unexpected control subclass '-1'
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- Executing [83047777777777@vicidial-auto:3] Hangup("Local/192*168*XX*XX*78600052@default-e957,1", "") in new stack
[Feb 1 15:04:04] VERBOSE[6897] logger.c: == Spawn extension (vicidial-auto, 83047777777777, 3) exited non-zero on 'Local/192*168*XX*XX*78600052@default-e957,1'
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- Executing [h@vicidial-auto:1] DeadAGI("Local/192*168*014*061*78600052@default-e957,1", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Feb 1 15:04:04] VERBOSE[6897] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16--------------- completed, returning 0
[Feb 1 15:04:04] VERBOSE[6896] logger.c: == Spawn extension (default, 78600052, 1) exited non-zero on 'Local/192*168*XX*XX*78600052@default-e957,2'
[Feb 1 15:04:04] VERBOSE[6896] logger.c: -- Executing [h@default:1] DeadAGI("Local/192*168*XX*XX*78600052@default-e957,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 15:04:04] VERBOSE[6896] logger.c: -- AGI Script agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
[Feb 1 15:04:07] VERBOSE[4369] logger.c: -- Accepting AUTHENTICATED call from 192.168.XX.XY:
> requested format = ulaw,
> requested prefs = (ulaw|gsm),
> actual format = ulaw,
> host prefs = (ulaw),
> priority = mine
[Feb 1 15:04:07] VERBOSE[6905] logger.c: -- Executing [8600052@default:1] MeetMe("IAX2/vicidial2-3870", "8600052|F") in new stack
[Feb 1 15:04:12] VERBOSE[6918] logger.c: -- Executing [58600052@default:1] MeetMe("Local/58600052@default-c0d5,2", "8600052|Fmq") in new stack
[Feb 1 15:04:12] VERBOSE[6917] logger.c: > Channel Local/58600052@default-c0d5,1 was answered.
[Feb 1 15:04:12] VERBOSE[6919] logger.c: -- Executing [8309@default:1] Answer("Local/58600052@default-c0d5,1", "") in new stack
[Feb 1 15:04:12] VERBOSE[6919] logger.c: -- Executing [8309@default:2] Monitor("Local/58600052@default-c0d5,1", "wav|20130201-150404_XXXXXXXXXXX_TESTI") in new stack
[Feb 1 15:04:12] VERBOSE[6919] logger.c: -- Executing [8309@default:3] Wait("Local/58600052@default-c0d5,1", "3600") in new stack
Agent presses hangup customer. The phone also hangs up like it should:
[Feb 1 15:04:19] VERBOSE[6905] logger.c: == Spawn extension (default, 8600052, 1) exited non-zero on 'IAX2/vicidial2-3870'
[Feb 1 15:04:19] VERBOSE[6905] logger.c: -- Executing [h@default:1] DeadAGI("IAX2/vicidial2-3870", "agi//127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------") in new stack
[Feb 1 15:04:19] VERBOSE[6905] logger.c: -- AGI Script
agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Feb 1 15:04:19] VERBOSE[6905] logger.c: -- Hungup 'IAX2/vicidial2-3870'
[Feb 1 15:04:20] VERBOSE[6894] logger.c: == Spawn extension (default, 78600052, 1) exited non-zero on 'IAX2/vicidial2-10924'
[Feb 1 15:04:20] VERBOSE[6894] logger.c: -- Executing [h@default:1] DeadAGI("IAX2/vicidial2-10924", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 15:04:20] VERBOSE[6894] logger.c: -- AGI Script
agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Feb 1 15:04:20] VERBOSE[6894] logger.c: -- Hungup 'IAX2/vicidial2-10924'
[Feb 1 15:04:20] VERBOSE[6918] logger.c: -- Hungup 'DAHDI/pseudo-78458710'
[Feb 1 15:04:20] VERBOSE[6918] logger.c: == Spawn extension (default, 58600052, 1) exited non-zero on 'Local/58600052@default-c0d5,2'
[Feb 1 15:04:20] VERBOSE[6918] logger.c: -- Executing [h@default:1] DeadAGI("Local/58600052@default-c0d5,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 15:04:20] VERBOSE[6886] logger.c: -- Executing [h@default:1] DeadAGI("IAX2/vicidial2-10110", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----17-----17") in new stack
[Feb 1 15:04:20] VERBOSE[6918] logger.c: -- AGI Script
agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Feb 1 15:04:20] VERBOSE[6919] logger.c: == Spawn extension (default, 8309, 3) exited non-zero on 'Local/58600052@default-c0d5,1'
[Feb 1 15:04:20] VERBOSE[6919] logger.c: -- Executing [h@default:1] DeadAGI("Local/58600052@default-c0d5,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
[Feb 1 15:04:20] VERBOSE[6886] logger.c: -- AGI Script
agi://127.0.0.1:4577/call_log--HVcauses ... -17-----17 completed, returning 0
[Feb 1 15:04:20] VERBOSE[6886] logger.c: == Spawn extension (default, 5000, 1) exited non-zero on 'IAX2/vicidial2-10110'
[Feb 1 15:04:20] VERBOSE[6886] logger.c: -- Hungup 'IAX2/vicidial2-10110'
[Feb 1 15:04:20] VERBOSE[6919] logger.c: -- AGI Script
agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
Hope there is not too much information...
These are just two phone calls without any other calls going on at the same time. I am using SIP-phones and this symptom is tested with different SIP-hardphones and with Zoiper classic.