Queue members timeout trouble

axyi · June 12, 2020, 10:10am

I have truble with queue module.
Here is a situation in line two members
parameters

[general_q]
defaultrule = hes
music = default
;context = queue_out
context = general_q_dtmf
announce-position = yes
announce-frequency = 40
announce-holdtime = no
;announce-holdtime = yes
periodic-announce = hello-12_14
periodic-announce-frequency = 60
autofill = yes
memberdelay = 0
strategy = rrmemory
timeout = 10
retry = 5
maxlen = 0
setinterfacevar = yes
setqueueentryvar = yes
setqueuevar = yes
ringinuse = no
wrapuptime = 0
weight = 0

the call arrives at the first one, it immediately answers 100 trying, then the call hangs and after ~ 6 seconds the terminal answers 486 busy, the call goes to the second operator and here is the oddity - the call goes to the operator for ~ 2 seconds and is canceled by the cancel asterisk.

In sngrep trace it i see that time between invite to first member and cancel to second equally 8 seconds

david551 · June 12, 2020, 10:46am

This sounds like it is dialplan related, but you haven’t provided the dialplan, and a verbose log showing the dialplan being executed…

axyi · June 14, 2020, 8:47am

If this helps you solve the problem
Call verbose

    -- Executing [751@from_oper:1] NoOp("SIP/oper_trunk-00000f10", "") in new stack
    -- Executing [751@from_oper:2] Set("SIP/oper_trunk-00000f10", "phoneid=<number_a>") in new stack
    -- Executing [751@from_oper:3] Set("SIP/oper_trunk-00000f10", "dialnum=<number_b>") in new stack
    -- Executing [751@from_oper:4] Macro("SIP/oper_trunk-00000f10", "more_calls") in new stack
    -- Executing [s@macro-more_calls:1] NoOp("SIP/oper_trunk-00000f10", "") in new stack
    -- Executing [s@macro-more_calls:2] Set("SIP/oper_trunk-00000f10", "text_in="<some text>"") in new stack
    -- Executing [s@macro-more_calls:3] Set("SIP/oper_trunk-00000f10", "text_in_sh="<some text>"") in new stack
    -- Executing [s@macro-more_calls:4] GotoIf("SIP/oper_trunk-00000f10", "1?end1") in new stack
    -- Goto (macro-more_calls,s,12)
    -- Executing [s@macro-more_calls:12] GotoIf("SIP/oper_trunk-00000f10", "1?end2") in new stack
    -- Goto (macro-more_calls,s,16)
    -- Executing [s@macro-more_calls:16] NoOp("SIP/oper_trunk-00000f10", "") in new stack
    -- Executing [751@from_oper:5] Macro("SIP/oper_trunk-00000f10", "t_kl_count") in new stack
    -- Executing [s@macro-t_kl_count:1] Set("SIP/oper_trunk-00000f10", "date_stat=2020-06-14") in new stack
    -- Executing [s@macro-t_kl_count:2] Set("SIP/oper_trunk-00000f10", "t_kl_count=0") in new stack
    -- Executing [s@macro-t_kl_count:3] GotoIf("SIP/oper_trunk-00000f10", "0?t_kl_undef") in new stack
    -- Executing [s@macro-t_kl_count:4] GotoIf("SIP/oper_trunk-00000f10", "1?post_id") in new stack
    -- Goto (macro-t_kl_count,s,15)
    -- Executing [s@macro-t_kl_count:15] NoOp("SIP/oper_trunk-00000f10", "") in new stack
    -- Executing [751@from_oper:6] Set("SIP/oper_trunk-00000f10", "GROUP()=incomm") in new stack
    -- Executing [751@from_oper:7] Set("SIP/oper_trunk-00000f10", "dat=14-06-2020") in new stack
    -- Executing [751@from_oper:8] Set("SIP/oper_trunk-00000f10", "CHANNEL(language)=ru") in new stack
    -- Executing [751@from_oper:9] Set("SIP/oper_trunk-00000f10", "in_quq="general_q"") in new stack
    -- Executing [751@from_oper:10] Set("SIP/oper_trunk-00000f10", "ODBC_WR_INCOMM_LINE(new,14-06-2020)=write") in new stack
    -- Executing [751@from_oper:11] Set("SIP/oper_trunk-00000f10", "cl_id_count=0") in new stack
    -- Executing [751@from_oper:12] Answer("SIP/oper_trunk-00000f10", "") in new stack
    -- Executing [751@from_oper:13] GotoIf("SIP/oper_trunk-00000f10", "0?numbyes:numbno") in new stack
    -- Goto (from_oper,751,15)
    -- Executing [751@from_oper:15] Goto("SIP/oper_trunk-00000f10", "auto_start,s,ocher19") in new stack
    -- Goto (auto_start,s,18)
    -- Executing [s@auto_start:18] Set("SIP/oper_trunk-00000f10", "QUEUE_PRIO=15") in new stack
    -- Executing [s@auto_start:19] MixMonitor("SIP/oper_trunk-00000f10", "/server/voice/14-06-2020/<number_a>_14062020_100234.wav,,cp /server/voice/14-06-2020/<number_a>_14062020_100234.wav /records/1592110954.7645_1592110954.7645.wav") in new stack
    -- Executing [s@auto_start:20] Set("SIP/oper_trunk-00000f10", "hangup_status=drop_in_queue") in new stack
  == Begin MixMonitor Recording SIP/oper_trunk-00000f10
    -- Executing [s@auto_start:21] Queue("SIP/oper_trunk-00000f10", ""general_q",t,,,7200") in new stack
    -- Started music on hold, class 'default', on channel 'SIP/oper_trunk-00000f10'
  == Using SIP RTP TOS bits 176
  == Using SIP RTP CoS mark 5
    -- Called SIP/member_1
    -- SIP/member_1-00000f11 is ringing
    -- Got SIP response 486 "Busy Here" back from XXX.XXX.XXX.XXX:20109
    -- SIP/member_1-00000f11 is busy
    -- Nobody picked up in 8000 ms
  == Using SIP RTP TOS bits 176
  == Using SIP RTP CoS mark 5
    -- Called SIP/member_2
    -- SIP/member_2-00000f12 is ringing
    -- Stopped music on hold on SIP/oper_trunk-00000f10
    -- <SIP/oper_trunk-00000f10> Playing 'queue-youarenext.ulaw' (language 'ru')
    -- Told SIP/oper_trunk-00000f10 in general_q their queue position (which was 1)
    -- <SIP/oper_trunk-00000f10> Playing 'queue-thankyou.ulaw' (language 'ru')
    -- Started music on hold, class 'default', on channel 'SIP/oper_trunk-00000f10'
  == Using SIP RTP TOS bits 176
  == Using SIP RTP CoS mark 5
    -- Called SIP/member_3
    -- SIP/member_3-00000f13 is ringing
  == Using SIP RTP TOS bits 176
  == Using SIP RTP CoS mark 5
    -- Called SIP/member_1
    -- SIP/member_1-00000f14 is ringing
    -- SIP/member_1-00000f14 answered SIP/oper_trunk-00000f10
    -- Stopped music on hold on SIP/oper_trunk-00000f10
    -- Channel SIP/member_1-00000f14 joined 'simple_bridge' basic-bridge <39c4bdb5-a9c8-4ef6-93ad-ddaf5ae670ab>
    -- Channel SIP/oper_trunk-00000f10 joined 'simple_bridge' basic-bridge <39c4bdb5-a9c8-4ef6-93ad-ddaf5ae670ab>
    -- Channel SIP/member_1-00000f14 left 'simple_bridge' basic-bridge <39c4bdb5-a9c8-4ef6-93ad-ddaf5ae670ab>
    -- Channel SIP/oper_trunk-00000f10 left 'simple_bridge' basic-bridge <39c4bdb5-a9c8-4ef6-93ad-ddaf5ae670ab>
  == Spawn extension (auto_start, s, 21) exited non-zero on 'SIP/oper_trunk-00000f10'
  == MixMonitor close filestream (mixed)
  == Executing [cp /server/voice/14-06-2020/<number_a>_14062020_100234.wav /records/1592110954.7645_1592110954.7645.wav]
  == End MixMonitor Recording SIP/oper_trunk-00000f10

Parts of dialplan

[ Context 'from_oper' created by 'pbx_config' ]
  '751' =>          1. NoOp()                                                   [extensions.conf:372]
                    2. Set(phoneid=${CALLERID(num)})                            [extensions.conf:373]
                    3. Set(dialnum=<number_b>)                                  [extensions.conf:374]
                    4. Macro(more_calls)                                        [extensions.conf:375]
                    5. Macro(t_kl_count)                                        [extensions.conf:376]
                    6. Set(GROUP()=incomm)                                      [extensions.conf:377]
                    7. Set(dat=${STRFTIME(,,%d-%m-%Y)})                         [extensions.conf:378]
                    8. Set(CHANNEL(language)=ru)                                [extensions.conf:379]
                    9. Set(in_quq="general_q")                                  [extensions.conf:380]
                    10. Set(ODBC_WR_INCOMM_LINE(new,${dat})=write)              [extensions.conf:381]
                    11. Set(cl_id_count=${ODBC_RD_CLIENT_ID_COUNT(${phoneid})}) [extensions.conf:382]
                    12. Answer()                                                [extensions.conf:383]
                    13. GotoIf($["${cl_id_count}"="1"]?numbyes:numbno)          [extensions.conf:384]
     [numbyes]      14. Set(cl_id=${ODBC_RD_CLIENT_ID2(${phoneid})})            [extensions.conf:385]
     [numbno]       15. GoTo(auto_start,s,ocher19)                              [extensions.conf:386]

[ Context 'macro-more_calls' created by 'pbx_config' ]
  's' =>            1. NoOp()                                     [extensions.conf:879]
                    2. Set(text_in="<some_text>")                 [extensions.conf:880]
                    3. Set(text_in_sh="<some_text>")              [extensions.conf:881]
                    4. GotoIf($[${GROUP_COUNT(incomm)}<8]?end1)   [extensions.conf:882]
     [send]         5. NoOp()                                     [extensions.conf:883]
                    6. Set(CURLOPT(conntimeout)=1)                [extensions.conf:884]
                    7. Set(curl_req=${SHELL(curl <> &)})          [extensions.conf:885]
                    8. Set(curl_req=${SHELL(curl <>)})            [extensions.conf:886]
                    9. Set(curl_req=${SHELL(curl <> &)})          [extensions.conf:887]
                    10. Set(curl_req=${SHELL(curl <> &)})         [extensions.conf:888]
                    11. Set(curl_req=${SHELL(curl <> &)})         [extensions.conf:889]
     [end1]         12. GotoIf($[${GROUP_COUNT(incomm)}<20]?end2) [extensions.conf:891]
                    13. Progress()                                [extensions.conf:893]
                    14. PlayBack(<>)                              [extensions.conf:894]
                    15. Hangup(17)                                [extensions.conf:895]
     [end2]         16. NoOp()                                    [extensions.conf:896]

[ Context 'macro-t_kl_count' created by 'pbx_config' ]
  's' =>            1. Set(date_stat=${STRFTIME(${EPOCH},,%Y-%m-%d)}) [extensions.conf:906]
                    2. Set(t_kl_count=${ODBC_RD_CLIENT_T_KL_COUNT(${phoneid})}) [extensions.conf:907]
                    3. GotoIf($[${t_kl_count} > 1]?t_kl_undef)    [extensions.conf:908]
                    4. GotoIf($[${t_kl_count} = 0]?post_id)       [extensions.conf:909]
                    5. Set(t_kl_c=${ODBC_RD_CLIENT_T_KL(${phoneid})}) [extensions.conf:911]
                    6. GotoIf($["${t_kl_c}"="0"]?t_kl_y)          [extensions.conf:912]
                    7. GotoIf($["${t_kl_c}"="1"]?t_kl_f)          [extensions.conf:913]
                    8. Goto(post_id)                              [extensions.conf:914]
     [t_kl_y]       9. Set(ODBC_WR_CHECK_ID_COUNT_1(${dialnum},${date_stat},${dialnum}-${date_stat})=wr_stat) [extensions.conf:916]
                    10. Goto(post_id)                             [extensions.conf:917]
     [t_kl_f]       11. Set(ODBC_WR_CHECK_ID_COUNT_2(${dialnum},${date_stat},${dialnum}-${date_stat})=wr_stat) [extensions.conf:919]
                    12. Goto(post_id)                             [extensions.conf:920]
     [t_kl_undef]   13. Set(ODBC_WR_CHECK_ID_COUNT_3(${dialnum},${date_stat},${dialnum}-${date_stat})=wr_stat) [extensions.conf:922]
                    14. Goto(post_id)                             [extensions.conf:923]
     [post_id]      15. NoOp()                                    [extensions.conf:925]

[ Context 'auto_start' created by 'pbx_config' ]
  's' =>            1. NoOp()                                     [extensions.conf:976]
     
     ...

     [ocher19]      18. Set(QUEUE_PRIO=15)                        [extensions.conf:998]
                    19. MixMonitor(/server/voice/${STRFTIME(,,%d-%m-%Y)}/${CALLERID(NUM)}_${STRFTIME(,,%d%m%Y_%H%M%S)}.wav,,cp /server/voice/${STRFTIME(,,%d-%m-%Y)}/${CALLERID(NUM)}_${STRFTIME(,,%d%m%Y_%H%M%S)}.wav /records/${UNIQUEID}_${CDR(linkedid)}.wav) [extensions.conf:999]
                    20. Set(hangup_status=drop_in_queue)          [extensions.conf:1000]
                    21. Queue(${in_quq},t,,,7200)                 [extensions.conf:1001]
                    22. Hangup()                                  [extensions.conf:1002]

And finaly scrinshot part of sngrep call flow

P.S.
Im temporary increase timout to 10 seconds.

david551 · June 14, 2020, 10:03am

You probably want to use the following option:

; If timeoutrestart is set to yes, then the timeout for an agent to answer is
; reset if a BUSY or CONGESTION is received. This can be useful if agents
; are able to cancel a call with reject or similar.

Without it, only the balance of your 10 second timeout is used when calling the next agent in the current round.

For future reference, in future please take logs from the log files, especially if time is of the essence of the problem, as the log files contain timestamps.

axyi · June 14, 2020, 8:31pm

Thanks, its work in this case! Sorry for the incorrectly formatted issue, in the future I will be more accurate.

system · July 14, 2020, 8:31pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.