Qubicle Debugging Guide

This guide will serve as a starting point for investigating issues that may arise during operation and testing of Qubicle. For example purposes we will assume that we have a queue configured with 2 recipients as members. The queue is set up to use ‘least_offers’ routing, and we have routed a callflow to the queue correctly.

Let us assume that we are placing test calls and that those calls are not being delivered, despite being REALLY SURE that we have a recipient logged in and ready.

NOTE Log messages in this guide are samples, the log lines while similar will NOT match exactly. NOTE also the timestamps may be skewed in these examples, also non relevant log lines are omitted from the examples.

Identifying a suspect session

We will place an inbound test call and handle it with a recipient. Then we will investigate the logs to attempt to isolate the delivery issue that we suspect may be a bug.

Locating the session id and tracking the session

All sessions in Qubicle have an id associated with them. We can use this id to identify all log messages associated with that particular session. Let us look at the logs at the point where we placed the test call.

14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:760 (<0.11983.6>) executing callflow f1d14e91f9059d1effed11c0f3f0c1a8f
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:761 (<0.11983.6>) account id 8b24e4ec970f0562c486e07fb0a1236c
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:762 (<0.11983.6>) request 5000@test.2600hz.com
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:763 (<0.11983.6>) to 5000@test.2600hz.com:5060
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:764 (<0.11983.6>) from 1001@test.2600hz.com
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:765 (<0.11983.6>) CID FirstTest LastT 1001
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:767 (<0.11983.6>) inception on-net: using attributes for an internal call
14:31:03.210 [info] |1_1053956289@10.69.1.127|cf_exe:770 (<0.11983.6>) authorizing id 5a7bce44c2697f0d5661d8c302c75ad8
14:31:03.223 [info] |1_1053956289@10.69.1.127|cf_exe:671 (<0.11983.6>) moving to action 'cf_qubicle'

We can see here that the call from a test device, 1001, has hit our test callflow and has correctly been routed to the qubicle callflow module. We will now look for the creation of the session that corresponds to this inbound call.

14:31:03.278 [debug] |0000000000|Undefined:Undefined (<0.1272.0>) Supervisor session_sup started session_proc:start_link(<<"1_1053956289@10.69.1.127_qubicle_session">>, call_session, {kapps_call,<<"1_1053956289@10.69.1.127">>,#Fun<kapps_call.3.99132614>,<<"kazoo_apps@debdev.2600hz...">>,...}) at pid <0.8161.4>

Here we see the session process being created. The session id is the first argument, in this case ”1_1053956289@10.69.1.127_qubicle_session”. You may notice that the session id is simply the callid with ‘qubicle_session’ appended to it. This makes it easy to locate a session that is associated with a given call.

Lets follow this session further as it progresses through Qubicle…

14:31:03.285 [info] |1_1053956289@10.69.1.127|cf_qubicle:71 (<0.11993.6>) joining <<"1_1053956289@10.69.1.127">> (<<"1_1053956289@10.69.1.127_qubicle_session">>) to queue <<"Main Test Queue">>
14:31:03.290 [info] |1_1053956289@10.69.1.127_qubicle_session|call_session:86 (<0.8161.4>) call_session(<<"1_1053956289@10.69.1.127_qubicle_session">>) joining queue a404631cc0da125da45534fc7355084f
14:31:03.292 [info] |a404631cc0da125da45534fc7355084f|queue_basic:144 (<0.1326.0>) session 1_1053956289@10.69.1.127_qubicle_session joining Main Test Queue

Here we see 3 log lines about the session joining a queue. The first comes from the qubicle callflow module, indicating that it is instructing the session to join the test queue “Main Test Queue”. The second is the call session process itself, actually sending a join message to the queue process. And finally the queue process is accepting the join, and placing the session in the queue.

Following the session offer

Thus far we have determined that our test call was correctly routed and handed off to Qubicle. We have verified that it was placed correctly into our test queue. Lets now examine the offer of the session to our recipient and try to figure out what is preventing the call from going through.

14:31:04.261 [info] |f70d510cb706a8412a3bcf9a80f9d98f|recipient_proc:415 (<0.8133.4>) received offer of (<<"1_1053956289@10.69.1.127_qubicle_session">>) from (<<"a404631cc0da125da45534fc7355084f">>)

Here we can see that the session is being offered from our test queue to a recipient. Take note of the recipient id “f70d510cb706a8412a3bcf9a80f9d98f” in this example. Lets search for that further in the logs to examine what it is doing while attempting to call out to our recipient device.

14:31:04.376 [info] |f70d510cb706a8412a3bcf9a80f9d98f|kz_endpoint:874 (<0.8133.4>) building a SIP endpoint

14:31:04.500 [debug] |f70d510cb706a8412a3bcf9a80f9d98f|kz_endpoint:183 (<0.8133.4>) formatted as {[{<<"Invite-Format">>,<<"username">>},{<<"To-User">>,<<"xlite_1">>},{<<"To-Username">>,<<"xlite_1">>},{<<"To-Realm">>,<<"test.2600hz.com">>},{<<"To-DID">>,<<"5000">>},{<<"Callee-ID-Name">>,<<"Account Admin">>},{<<"Callee-ID-Number">>,<<"5000">>},{<<"Outbound-Callee-ID-Name">>,<<"Account Admin">>},{<<"Outbound-Callee-ID-Number">>,<<"5000">>},{<<"Endpoint-ID">>,<<"f6d11579fcb52503a9599818852ac102">>},{<<"Codecs">>,[<<"PCMA">>,<<"PCMU">>]},{<<"Presence-ID">>,<<"xlite_1@test.2600hz.com">>},{<<"Custom-SIP-Headers">>,{[{<<"X-KAZOO-AOR">>,<<"sip:xlite_1@test.2600hz.com">>}]}},{<<"Custom-Channel-Vars">>,{[{<<"SIP-Invite-Domain">>,<<"test.2600hz.com">>},{<<"Media-Encryption-Enforce-Security">>,false},{<<"Account-ID">>,<<"8b24e4ec970f0562c486e07fb0a1236c">>},{<<"Owner-ID">>,<<"f70d510cb706a8412a3bcf9a80f9d98f">>},{<<"Authorizing-Type">>,<<"device">>},{<<"Authorizing-ID">>,<<"f6d11579fcb52503a9599818852ac102">>}]}}]}

14:55:22.904 [info] |f70d510cb706a8412a3bcf9a80f9d98f|agent_recipient:251 (<0.8133.4>) placing outbound call to recipient with callid <<"agent_recipient_1_1053956289@10.69.1.127-1">>

Here we can see our recipient process (identified by the recipient id) constructing a SIP endpoint to place the outbound call. This endpoint contains some useful information about the call that we can use for further debugging. Let us look at the outbound call as it is processed by Kazoo by searching for the callid, is this case “agent_recipient_1_1295059990@10.69.1.127-1”. NOTE that the outbound callid to the recipient also contains the inbound callid, making them very easy to associate.

Examining the outbound call

Now we have found the callid of our call out to the recipient for the offer of our test session. Thus far we have proved that the call was routed correctly, handled correctly by Qubicle up to and including the offer process, and that the recipient process correctly attempted to place an outbound call to deliver the session to the recipient.

Let us now investigate why that call is not working properly by searching for the outbound callid and examining the logs further.

14:31:04.939 [debug] |agent_recipient_1_1053956289@10.69.1.127-0|ecallmgr_originate:570 (<0.26118.4>) executing originate on freeswitch@debdev.2600hz.com: {call_timeout=20,originate_timeout=20,origination_caller_id_number='1001',origination_caller_id_name='FirstTest LastT',effective_caller_id_number='1001',effective_caller_id_name='FirstTest LastT',ecallmgr_Fetch-ID='451d1e8838e9d563b18ab9771e52b753',ecallmgr_Ecallmg
r-Node='ecallmgr@debdev.2600hz.com',ecallmgr_Call-Interaction-ID='63645852664-be33d507',ecallmgr_Agent-ID='f70d510cb706a8412a3bcf9a80f9d98f',ecallmgr_Retain-CID='true',ecallmgr_Request-ID='a7fdb824aa2a2a674ed3a89437445174',ecallmgr_Authorizing-ID='5a7bce44c2697f0d5661d8c302c75ad8',ecallmgr_Account-ID='8b24e4ec970f0562c486e07fb0a1236c',local_var_clobber='true'}  'set:intercept_unbridged_only=true,intercept:1_105395628
9@10.69.1.127' inline

14:31:05.139 [debug] |agent_recipient_1_1053956289@10.69.1.127-0|ecallmgr_originate:586 (<0.26118.4>) error originating: -ERR DESTINATION_OUT_OF_ORDER

Here we see the origination of the call, and a subsequent error as well. Our outbound call to the recipient has failed to originate because the destination is out of order!

In this particular instance that is caused by the recipient device not being registered correctly.

Conclusion

We have tracked a test call through Qubicle and identified why the call failed to be delivered to the agent. This, while a simplistic example, should serve as a guide on how to approach examining the logs for problems with Qubicle.

Take a note of how all log messages include ID’s that are relevant and can be used to search for further log lines. Also keep in mind that if there are multiple nodes involved, the entire log stream may span those nodes.

On this Page