Logging for OCC IVG Avaya

OCC logs, by default located at (x86)/Virtual Hold Technology/Outbound Contact Client/logs, contain information relating to OCC startup, registration, callback initiation, and HTTP CreateSession requests and responses. The log levels and paths can be configured by modifying the Peripheral Monitor site.config file.

Configuring logs

OCC logs are configured to write to the paths and levels specified in the site.config file which resides in the OCC working directory.

Note:

  • OCC log file paths configured in the site.config file require the use of forward slashes.
  • When manually configuring the the site.config file, save the file when finished and restart the VHT® software Outbound Contact Client Service.

Log Levels

The lager_file_backed parameter values in the OCC site.config file can be changed to increase or decrease the log levels for each log file type.

The following log levels are available:

  • info - information level logging. Includes high-level operational events.
  • error - error level logging. Includes info level logs and all error events.
  • debug - debug level logging. Includes info level, error level, and all low-level operational events

The highlighted syntax in the site.config file sample below indicates where the log level can be changed:

{lager, [{handlers, [{lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/error.log"}, {level, error}]}, {lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/occ.log"}, {level, info}]} ]} ]}

Log paths

In the sample below, the lager_file_backend parameter values indicate that two types of log files will be written:

{lager, [{handlers, [{lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/error.log"}, {level, error}]}, {lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/occ.log"}, {level, info}]} ]} ]}
  • The error.log will write at the error level to:

C:\Program Files (x86)\Virtual Hold Technology\Outbound Contact Client\log\error.log

  • The occ.log will write at the info level to:

C:\Program Files (x86)\Virtual Hold Technology\Outbound Contact Client\log\occ.log

In the sample below, the lager_file_backend parameter values indicate three types of log files that will be written:

{lager, [{handlers, [{lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/occ.log"}, {level, info}]}, {lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/error.log"}, {level, error}]}, {lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/debug.log"}, {level, debug}]} ]} ]}
  • The occ.log will write at the info level to:

C:\Program Files (x86)\Virtual Hold Technology\VHLogs\Logs\Outbound Contact Client\occ.log

  • The error.log will write at the error level to:

C:\Program Files (x86)\Virtual Hold Technology\VHLogs\Logs\Outbound Contact Client\error.log

  • The debug.log will write at the debug level to:

C:\Program Files (x86)\Virtual Hold Technology\VHLogs\Logs\Outbound Contact Client\debug.log

return to top

Log levels

The lager_file_backed parameter values in the OCC site.config file can be changed to increase or decrease the log levels for each log file type.

The following log levels are available:

  • info - information level logging. Includes high-level operational events.
  • error - error level logging. Includes info level logs and all error events.
  • debug - debug level logging. Includes info level, error level, and all low-level operational events

The highlighted syntax in the site.config file sample below indicates where the log level can be changed:

{lager, [{handlers, [{lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/error.log"}, {level, error}]}, {lager_file_backend, [{file, "C:/Program Files (x86)/Virtual Hold Technology/Outbound Contact Client/log/occ.log"}, {level, info}]} ]} ]}

return to top

Logging for OCC IVG (Avaya)

The following log samples are from the occ.log file, and are written at the info level. They represent the essential operational events for registering the IVR, OCC startup, and callback processing.

Register IVR

The OCC verifies QueueManager is up and running before trying to register the IVR. Search "queue_manager_node" to locate these events.

  • The OCC verifies QueueManager is up and running before trying to register the IVR.
2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:172 QueueManager node ({'vht_ha_qm@vht.qalab.local',"10.10.10.10","9999"}) is active2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:174 RoundRobin Next QueueManger Info: {"vht.qalab.local",9999}
  • OCC registers the IVR.
2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:172 QueueManager node ({'vht_ha_qm@vht.qalab.local',"10.10.10.10","9999"}) is active2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:174 RoundRobin Next QueueManger Info: {"vht.qalab.local",9999}2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:verify_node:185 QueueManager Connected at node 'vht_ha_qm@vht.qalab.local', Register IVR2016-10-11 12:00:10.197 [info] <0.251.0>@disposition_listener:start_mochiweb:116 Starting http server on port: 4153

Startup and Registration

Search "started" to find the OCC startup and registration process events.

  • The internal OCC applications start on the same node.
2016-10-11 11:58:36.480 [info] <0.7.0> Application lager started on node 'vht_remote_client@vht.qalab.local'2016-10-11 11:58:36.496 [info] <0.170.0>@rr:init:88 roundrobin_server starting2016-10-11 11:58:36.496 [info] <0.7.0> Application roundrobin started on node 'vht_remote_client@vht.qalab.local'2016-10-11 11:58:36.496 [info] <0.174.0>@erlang_app_controller_app:start:14 erlang_app_controller_app: erlang_app_controller application started2016-10-11 11:58:36.496 [info] <0.174.0>@erlang_app_controller_sup:start_link:30 Started Supervisor: erlang_app_controller_sup, Application options: [{max_restart_count,8},{restart_period_seconds,120}], Application list: [[{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}],[{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]]2016-10-11 11:58:36.496 [info] <0.175.0>@erlang_app_controller_sup:init:47 Init childspecs, [{vht_outbound_contact_client_controller,{app_control_server,start_link,[[{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}]]},permanent,1000,worker,[app_control_server]},{qmcl_controller,{app_control_server,start_link,[[{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]]},permanent,1000,worker,[app_control_server]}], are ok2016-10-11 11:58:36.512 [info] <0.175.0>@app_control_server:start_link:32 AppConfig: [{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}]2016-10-11 11:58:36.512 [info] <0.176.0>@app_control_server:init:53 Init: [{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}]2016-10-11 11:58:36.512 [info] <0.175.0>@app_control_server:start_link:32 AppConfig: [{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]2016-10-11 11:58:36.512 [info] <0.177.0>@app_control_server:init:53 Init: [{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]2016-10-11 11:58:36.512 [info] <0.7.0> Application erlang_app_controller started on node 'vht_remote_client@vht.qalab.local'
  • The ErlangAppController starts the vht_outbound_contact_client.
2016-10-11 11:58:36.496 [info] <0.174.0>@erlang_app_controller_app:start:14 erlang_app_controller_app: erlang_app_controller application started2016-10-11 11:58:36.496 [info] <0.174.0>@erlang_app_controller_sup:start_link:30 Started Supervisor: erlang_app_controller_sup, Application options: [{max_restart_count,8},{restart_period_seconds,120}], Application list: [[{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}],[{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]]2016-10-11 11:58:36.496 [info] <0.175.0>@erlang_app_controller_sup:init:47 Init childspecs, [{vht_outbound_contact_client_controller,{app_control_server,start_link,[[{app_name,vht_outbound_contact_client},{app_spec,{vht_outbound_contact_client_supervisor,{sup,start_link,[]},permanent,1000,supervisor,[sup]}},{system_management_notification,true}]]},permanent,1000,worker,[app_control_server]},{qmcl_controller,{app_control_server,start_link,[[{app_name,qmcl},{app_spec,{qmcl_supervisor,{qmcl_sup,start_link,[]},permanent,1000,supervisor,[qmcl_sup]}}]]},permanent,1000,worker,[app_control_server]}], are ok
  • The configuration attributes from the site.config file are read in as Environment Variables.
2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_group_name,"IVR"}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {exclude_connections_on_failure,true}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {disposition_url,"http://10.10.10.10:4153/vht/occ"}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {included_applications,[]}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {disposition_timeout,55000}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {default_connection_attributes,[{outdial_http_options,[{timeout,5000},{connect_timeout,5000}]},{request_header,[{"Accept","application/x-www-form-urlencoded"},{"Content-Type","application/x-www-form-urlencoded"}]},{enable_amd,true},{ring_no_answer_timeout,50000},{ccxml_fetch_timeout,5000},{tenant,"VHT"}]}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {time_to_exclude_on_failure_ms,150000}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {load_balanced_connections,[[{outdial_url,"http://10.10.10.10:8040/createsession"},{sip_endpoint,"10.10.10.10"},{failure_destination,"sip:55312@10.10.10.10"},{dnis,"outbound"},{vht_outbound_dialer_uri,"http://10.10.10.10:8080/vht-ivg/vht_hvp.ccxml"},{ani,"sip:3308675309@10.10.10.10"},{node_id,5}]]}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {voice_platform,ivg_hvp_plugin}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_server_name,"vht.qalab.local"}2016-10-11 11:58:36.625 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivg_environment, avaya},2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {queue_manager_connection_ping_in_seconds,15}2016-10-11 11:58:36.652 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_port_send_interval_ms,2000}
  • QMCL opens a socket between OCC and QueueManager.
2016-10-11 11:58:40.806 [info] <0.226.0>@qmcl_tcp:establish_connection:153 Attempting to connect to "vht.qalab.local":99992016-10-11 11:58:41.825 [info] <0.226.0>@qmcl_tcp:establish_connection:157 Opened socket to "vht.qalab.local":99992016-10-11 11:58:52.707 [info] <0.185.0>@request_listener:query_queue_manager_node:172 QueueManager node ({'vht_ha_qm@vht.qalab.local',"10.10.10.10","9999"}) is active2016-10-11 11:58:52.707 [info] <0.185.0>@request_listener:query_queue_manager_node:174 RoundRobin Next QueueManger Info: {"vht.qalab.local",9999}2016-10-11 11:58:52.712 [info] <0.185.0>@request_listener:verify_node:185 QueueManager Connected at node 'vht_ha_qm@vht.qalab.local', Register IVR2016-10-11 11:58:52.820 [info] <0.185.0>@request_listener:register_ivr:343 Registering IVR with Queue Manager. ServerName:"vht", Send Interval:20002016-10-11 11:58:52.957 [info] <0.185.0>@request_listener:register_ivr:347 QMCL Send - Register Message: <<"VHT_QMCL0710678000076<MsgId>86</MsgId><ReqId>0d15f99d-939c-4596-95a3-748134abf48e</ReqId><SerName>vht</SerName><IVRPSInt>2000</IVRPSInt>">>2016-10-11 11:58:52.957 [info] <0.226.0>@qmcl_tcp:handle_info:125 Received Message: <<"VHT_QMCL080001000005A<MsgId>86</MsgId><RetValue>1</RetValue><ReqId>0d15f99d-939c-4596-95a3-748134abf48e</ReqId>">>2016-10-11 11:58:53.006 [info] <0.226.0>@qmcl_tcp:process_parsed_message:173 ParsedMessage: {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"0d15f99d-939c-4596-95a3-748134abf48e"}]}}2016-10-11 11:58:53.006 [info] <0.226.0>@request_listener:message_processor:77 Message: {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"0d15f99d-939c-4596-95a3-748134abf48e"}]}}2016-10-11 11:58:53.006 [info] <0.226.0>@qmcl_tcp:process_reply:196 Sending QMCL reply {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"0d15f99d-939c-4596-95a3-748134abf48e"}]}} to {<0.185.0>,#Ref<0.0.0.842>}2016-10-11 11:58:53.006 [info] <0.185.0>@request_listener:register_ivr:349 QMCL Receive - Register Message Response: {ok,{<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"0d15f99d-939c-4596-95a3-748134abf48e"}]}}}
  • The ErlangAppController receives a message from the SystemManagement page to stop the vht_outbound_contact_client.
2016-10-11 12:00:00.097 [info] <0.176.0>@app_control_server:handle_call:61 stop_erlang_app: vht_outbound_contact_client2016-10-11 12:00:00.098 [info] <0.188.0>@connection_failure_manager:terminate:60 terminate shutdown, {state,[],true}2016-10-11 12:00:00.098 [info] <0.187.0>@disposition_listener:terminate:95 Terminating. Reason: shutdown2016-10-11 12:00:00.098 [info] <0.185.0>@request_listener:terminate:159 Terminate reason: shutdown2016-10-11 12:00:00.098 [info] <0.185.0>@request_listener:terminate:160 Terminate State: {state,"IVR","vht",2000,5555,5555,4444,4444,[],{component_heartbeat_state,{rabbitmq_connection_info,#Ref<0.0.0.589>,<0.212.0>,<0.221.0>},{component_heartbeat_options,peripheral,<<"Outbound Contact Client">>,"vht.qalab.local",full,started,<<"{}">>,undefined}},[[[{outdial_url,"http://10.10.10.10:8040/createsession"},{sip_endpoint,"10.10.10.10"},{failure_destination,"sip:55312@10.10.10.10"},{dnis,"outbound"},{vht_outbound_dialer_uri,"http://10.10.10.10:8080/vht-ivg/vht_hvp.ccxml"},{ani,"sip:3308675309@10.10.10.10"},{node_id,5}]]],[],[]}
  • ErlangAppController receives a message from the SystemManagement page to start the vht_outbound_contact_client.
2016-10-11 12:00:09.195 [info] <0.176.0>@app_control_server:handle_call:64 start_erlang_app: vht_outbound_contact_client
  • The configuration attributes from the site.config file are read in as Environment Variables.
2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_group_name,"IVR"}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {exclude_connections_on_failure,true}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {disposition_url,"http://10.10.10.10:4153/vht/occ"}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {included_applications,[]}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {disposition_timeout,55000}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {default_connection_attributes,[{outdial_http_options,[{timeout,5000},{connect_timeout,5000}]},{request_header,[{"Accept","application/x-www-form-urlencoded"},{"Content-Type","application/x-www-form-urlencoded"}]},{enable_amd,true},{ring_no_answer_timeout,50000},{ccxml_fetch_timeout,5000},{tenant,"VHT"}]}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {time_to_exclude_on_failure_ms,150000}2016-10-11 12:00:09.195 [info] <0.175.0>@sup:print_env:49 Environment Variable: {load_balanced_connections,[[{outdial_url,"http://10.10.10.10:8040/createsession"},{sip_endpoint,"10.10.10.10"},{failure_destination,"sip:55312@10.10.10.10"},{dnis,"outbound"},{vht_outbound_dialer_uri,"http://10.10.10.10:8080/vht-ivg/vht_hvp.ccxml"},{ani,"sip:3308675309@10.10.10.10"},{node_id,5}]]}2016-10-11 12:00:09.196 [info] <0.175.0>@sup:print_env:49 Environment Variable: {voice_platform,ivg_hvp_plugin}2016-10-11 12:00:09.196 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivg_environment, avaya},2016-10-11 12:00:09.196 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_server_name,"vht.qalab.local"}2016-10-11 12:00:09.196 [info] <0.175.0>@sup:print_env:49 Environment Variable: {queue_manager_connection_ping_in_seconds,15}2016-10-11 12:00:09.196 [info] <0.175.0>@sup:print_env:49 Environment Variable: {ivr_port_send_interval_ms,2000}
  • QMCL opens a socket between OCC and QueueManager.
2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:172 QueueManager node ({'vht_ha_qm@vht.qalab.local',"10.10.10.10","9999"}) is active2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:query_queue_manager_node:174 RoundRobin Next QueueManger Info: {"vht.qalab.local",9999}2016-10-11 12:00:10.197 [info] <0.249.0>@request_listener:verify_node:185 QueueManager Connected at node 'vht_ha_qm@vht.qalab.local', Register IVR2016-10-11 12:00:10.197 [info] <0.251.0>@disposition_listener:start_mochiweb:116 Starting http server on port: 41532016-10-11 12:00:10.310 [info] <0.249.0>@request_listener:register_ivr:343 Registering IVR with Queue Manager. ServerName:"vht", Send Interval:20002016-10-11 12:00:10.310 [info] <0.249.0>@request_listener:register_ivr:347 QMCL Send - Register Message: <<"VHT_QMCL0710678000076<MsgId>86</MsgId><ReqId>f5f7137a-9cac-48fb-b2b6-91a2412132ce</ReqId><SerName>vht</SerName><IVRPSInt>2000</IVRPSInt>">>2016-10-11 12:00:10.310 [info] <0.226.0>@qmcl_tcp:handle_info:125 Received Message: <<"VHT_QMCL080001000005A<MsgId>86</MsgId><RetValue>1</RetValue><ReqId>f5f7137a-9cac-48fb-b2b6-91a2412132ce</ReqId>">>2016-10-11 12:00:10.311 [info] <0.226.0>@qmcl_tcp:process_parsed_message:173 ParsedMessage: {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"f5f7137a-9cac-48fb-b2b6-91a2412132ce"}]}}2016-10-11 12:00:10.311 [info] <0.226.0>@request_listener:message_processor:77 Message: {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"f5f7137a-9cac-48fb-b2b6-91a2412132ce"}]}}2016-10-11 12:00:10.311 [info] <0.226.0>@qmcl_tcp:process_reply:196 Sending QMCL reply {<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"f5f7137a-9cac-48fb-b2b6-91a2412132ce"}]}} to {<0.249.0>,#Ref<0.0.0.1624>}2016-10-11 12:00:10.311 [info] <0.249.0>@request_listener:register_ivr:349 QMCL Receive - Register Message Response: {ok,{<<"08">>,<<"00010">>,90,{struct,[{'MsgId',"86"},{'RetValue',"1"},{'ReqId',"f5f7137a-9cac-48fb-b2b6-91a2412132ce"}]}}}

Callback Initiation

Search "initiate_callback" or "starting callback" to locate a VH CallID received from QueueManager in the occ.log files.

  • OCC receives a callback request from QueueManager containing the VH CallID and QueueID for the callback.
2016-10-11 12:00:52.030 [info] <0.226.0>@qmcl_tcp:handle_info:125 Received Message: <<"VHT_QMCL0700010000082<MsgId>73</MsgId><CallId>V005D000000008911102016120049891</CallId><IVRExtension></IVRExtension><QId>VHT_Test</QId><ReqId>0</ReqId>">>2016-10-11 12:00:52.031 [info] <0.226.0>@qmcl_tcp:process_parsed_message:173 ParsedMessage: {<<"07">>,<<"00010">>,130,{struct,[{'MsgId',"73"},{'CallId',"V005D000000008911102016120049891"},{'IVRExtension',[]},{'QId',"VHT_Test"},{'ReqId',"0"}]}}2016-10-11 12:00:52.031 [info] <0.249.0>@request_listener:initiate_callback:196 "V005D000000008911102016120049891" Starting callback
  • OCC requests and receives from QueueManager the segment associated with the VH CallID. The Segment and QueueID are used to select the IVR platform connections for issuing HTTP CreateSession requests.
2016-10-11 12:00:52.031 [info] <0.249.0>@request_listener:get_data_value:307 "V005D000000008911102016120049891" -> QMCL Send - Get Data Value. DataValueName: "Pilot Number". DataValueNumber: 39.2016-10-11 12:00:52.032 [info] <0.249.0>@request_listener:get_data_value:309 "V005D000000008911102016120049891" -> QMCL Send - Get Data Value Request: <<"VHT_QMCL071067800008C<MsgId>53</MsgId><ReqId>e339dde1-8ad2-4c19-b636-5cc07a862354</ReqId><CallId>V005D000000008911102016120049891</CallId><DataName>39</DataName>">>2016-10-11 12:00:52.032 [info] <0.226.0>@qmcl_tcp:handle_info:125 Received Message: <<"VHT_QMCL0800010000091<MsgId>53</MsgId><CallId>V005D000000008911102016120049891</CallId><DataValue>48231</DataValue><ReqId>e339dde1-8ad2-4c19-b636-5cc07a862354</ReqId>">>2016-10-11 12:00:52.033 [info] <0.226.0>@qmcl_tcp:process_parsed_message:173 ParsedMessage: {<<"08">>,<<"00010">>,145,{struct,[{'MsgId',"53"},{'CallId',"V005D000000008911102016120049891"},{'DataValue',"48231"},{'ReqId',"e339dde1-8ad2-4c19-b636-5cc07a862354"}]}}2016-10-11 12:00:52.033 [info] <0.226.0>@request_listener:message_processor:77 Message: {<<"08">>,<<"00010">>,145,{struct,[{'MsgId',"53"},{'CallId',"V005D000000008911102016120049891"},{'DataValue',"48231"},{'ReqId',"e339dde1-8ad2-4c19-b636-5cc07a862354"}]}}2016-10-11 12:00:52.033 [info] <0.226.0>@qmcl_tcp:process_reply:196 Sending QMCL reply {<<"08">>,<<"00010">>,145,{struct,[{'MsgId',"53"},{'CallId',"V005D000000008911102016120049891"},{'DataValue',"48231"},{'ReqId',"e339dde1-8ad2-4c19-b636-5cc07a862354"}]}} to {<0.249.0>,#Ref<0.0.0.2092>}2016-10-11 12:00:52.033 [info] <0.249.0>@request_listener:get_data_value:311 "V005D000000008911102016120049891" -> QMCL Receive - Get Data Value Response: {ok,{<<"08">>,<<"00010">>,145,{struct,[{'MsgId',"53"},{'CallId',"V005D000000008911102016120049891"},{'DataValue',"48231"},{'ReqId',"e339dde1-8ad2-4c19-b636-5cc07a862354"}]}}}2016-10-11 12:00:52.033 [info] <0.249.0>@request_listener:get_data_value:313 "V005D000000008911102016120049891" -> QMCL Receive - DataValue: "Pilot Number" = "48231"2016-10-11 12:00:52.033 [info] <0.249.0>@request_listener:initiate_callback:198 "V005D000000008911102016120049891" -> Segment: "48231"2016-10-11 12:00:52.033 [info] <0.249.0>@request_listener:initiate_callback:199 "V005D000000008911102016120049891" -> QueueId: "VHT_Test"
  • OCC sends acknowledgement to QueueManager that the callback request has been received.
2016-10-11 12:00:52.040 [info] <0.249.0>@request_listener:send_make_callback_response:253 "V005D000000008911102016120049891" -> QMCL Send - Make Callback Response: <<"VHT_QMCL0810678000077<MsgId>73</MsgId><ReqId>0</ReqId><RetValue>1</RetValue><TIP>5555</TIP><TIPA>5555</TIPA><TOP>4444</TOP><TOPA>4444</TOPA>">>2016-10-11 12:00:52.040 [info] <0.249.0>@request_listener:send_make_callback_response:255 "V005D000000008911102016120049891" -> QMCL Receive - Make Callback Response Result: {ok,there_is_no_message}
  • OCC requests and receives the Outbound IVR variables for the VH CallID received from QueueManager.
2016-10-11 12:00:52.055 [info] <0.289.0>@request_listener:get_outbound_ivr_vars:288 "V005D000000008911102016120049891" -> QMCL Send - Get Outbound IVR Vars Request: <<"VHT_QMCL0710678000075<MsgId>57</MsgId><ReqId>5321123f-920f-4e2c-b49b-2e4c86a377b6</ReqId><CallId>V005D000000008911102016120049891</CallId>">>2016-10-11 12:00:52.055 [info] <0.226.0>@qmcl_tcp:handle_info:125 Received Message: <<"VHT_QMCL08000100000DE<MsgId>57</MsgId><RetValue>1</RetValue><Val>|70933020|@10.10.10.10|VHT_Test|1|sip:55312@10.10.10.10|sip:55313@10.10.10.10|120|120|1|0|0|0|0|0||Initial FIFO Callback|</Val><ReqId>5321123f-920f-4e2c-b49b-2e4c86a377b6</ReqId>">>2016-10-11 12:00:52.056 [info] <0.226.0>@qmcl_tcp:process_parsed_message:173 ParsedMessage: {<<"08">>,<<"00010">>,222,{struct,[{'MsgId',"57"},{'RetValue',"1"},{'Val',"|70933020|@10.10.10.10|VHT_Test|1|sip:55312@10.10.10.10|sip:55313@10.10.10.10|120|120|1|0|0|0|0|0||Initial FIFO Callback|"},{'ReqId',"5321123f-920f-4e2c-b49b-2e4c86a377b6"}]}}2016-10-11 12:00:52.056 [info] <0.226.0>@request_listener:message_processor:77 Message: {<<"08">>,<<"00010">>,222,{struct,[{'MsgId',"57"},{'RetValue',"1"},{'Val',"|70933020|@10.10.10.10|VHT_Test|1|sip:55312@10.10.10.10|sip:55313@10.10.10.10|120|120|1|0|0|0|0|0||Initial FIFO Callback|"},{'ReqId',"5321123f-920f-4e2c-b49b-2e4c86a377b6"}]}}2016-10-11 12:00:52.056 [info] <0.226.0>@qmcl_tcp:process_reply:196 Sending QMCL reply {<<"08">>,<<"00010">>,222,{struct,[{'MsgId',"57"},{'RetValue',"1"},{'Val',"|70933020|@10.10.10.10|VHT_Test|1|sip:55312@10.10.10.10|sip:55313@10.10.10.10|120|120|1|0|0|0|0|0||Initial FIFO Callback|"},{'ReqId',"5321123f-920f-4e2c-b49b-2e4c86a377b6"}]}} to {<0.289.0>,#Ref<0.0.0.2099>}2016-10-11 12:00:52.057 [info] <0.289.0>@request_listener:get_outbound_ivr_vars:290 "V005D000000008911102016120049891" -> QMCL Receive - Get Outbound IVR Vars Response: {ok,{<<"08">>,<<"00010">>,222,{struct,[{'MsgId',"57"},{'RetValue',"1"},{'Val',"|70933020|@10.10.10.10|VHT_Test|1|sip:55312@10.10.10.10|sip:55313@10.10.10.10|120|120|1|0|0|0|0|0||Initial FIFO Callback|"},{'ReqId',"5321123f-920f-4e2c-b49b-2e4c86a377b6"}]}}}2016-10-11 12:00:52.060 [info] <0.289.0>@request_listener:get_outbound_ivr_vars:293 "V005D000000008911102016120049891" -> QMCL Receive - Outbound IVR Vars: {obIVRVarsRecord,[],"70933020","@10.10.10.10","VHT_Test","1","sip:55312@10.10.10.10","sip:55313@10.10.10.10","120","120","1","0","0","0","0","0",[],"Initial FIFO Callback",[]}
  • OCC informs QueueManager that an outbound line is being seized to progress the state of the callback request.
2016-10-11 12:00:52.060 [info] <0.289.0>@request_listener:set_data_value:318 "V005D000000008911102016120049891" -> QMCL Send - Set Data Value. DataValueName: "IVR State". Value: "Seize Outbound Line". DataValueNumber: 11.2016-10-11 12:00:52.060 [info] <0.289.0>@request_listener:set_data_value:320 "V005D000000008911102016120049891" -> QMCL Send - Set Data Value Request: <<"VHT_QMCL0710678000088<MsgId>137</MsgId><CallId>V005D000000008911102016120049891</CallId><DName>11</DName><DVal>Seize Outbound Line</DVal><MakeRPC>0</MakeRPC>">>2016-10-11 12:00:52.060 [info] <0.289.0>@request_listener:set_data_value:324 "V005D000000008911102016120049891" -> QMCL Receive - Set Data Value Response: ok

HTTP CreateSession Request and Response

Search "attempting connection" or "outdial_url" to locate the HTTP CreateSession request process in the occ.log files.

  • OCC uses an out dial connection from a connection list designated in the site.config file to issue an HTTP CreateSession request to the IVR platform web service.
2016-10-11 12:00:52.067 [info] <0.289.0>@ivg_hvp_plugin:attempt_connection:31 "V005D000000008911102016120049891" -> Attempting connection: [{outdial_url,"http://10.10.10.10:8040/createsession"},{sip_endpoint,"10.10.10.10"},{failure_destination,"sip:55312@10.10.10.10"},{dnis,"outbound"},{vht_outbound_dialer_uri,"http://10.10.10.10:8080/vht-ivg/vht_hvp.ccxml"},{ani,"sip:3308675309@10.10.10.10"},{node_id,5}]2016-10-11 12:00:52.073 [info] <0.289.0>@ivg_hvp_translator:body_structure:130 "V005D000000008911102016120049891" -> Http request parameters: [{"uri","http://10.10.10.10:8080/vht-ivg/vht_hvp.ccxml"},{"eventsource","http://10.10.10.10:4153/vht/occ/V005D000000008911102016120049891"},{"timeout","5s"},{"remote","sip:70933020@10.10.10.10"},{"local","sip:3308675309@10.10.10.10"},{"connecttimeout","50s"},{"aai","00FA080005000157FD0CB4;encoding=hex"},{"key","outbound"},{"max-age",86400},{"userdata",{struct,[{"tenant","VHT"},{"enable_amd",true},{"failure_destination","sip:55312@10.10.10.10"},{"interaction_id","V005D000000008911102016120049891"}]}}]2016-10-11 12:00:52.074 [info] <0.289.0>@ivg_hvp_plugin:send_next_request:43 "V005D000000008911102016120049891" -> Http request method: post2016-10-11 12:00:52.074 [info] <0.289.0>@ivg_hvp_plugin:send_next_request:44 "V005D000000008911102016120049891" -> Http request options: {[{timeout,5000},{connect_timeout,5000}],[{sync,true}]}2016-10-11 12:00:52.106 [info] <0.289.0>@ivg_hvp_plugin:try_send_request:56 "V005D000000008911102016120049891" -> httpResult: {ok,{{"HTTP/1.1",200,"OK"},[{"date","Tue, 11 Oct 2016 16:00:49 GMT"},{"server","hcc/1.0"},{"content-length","17"},{"content-type","application/x-www-form-urlencoded"}],"session.id=s74011"}}2016-10-11 12:00:52.106 [info] <0.289.0>@callback:send_callback_request:172 "V005D000000008911102016120049891" -> Request successful, waiting for disposition timeout: 55000 milliseconds2016-10-11 12:00:57.656 [info] <0.251.0>@disposition_listener:handle_cast:64 Disposition Received. Method: 'POST', Path: "/vht/occ/V005D000000008911102016120049891", QueryStringData: [], Content-Type: "application/x-www-form-urlencoded", Body: "event=connected&name=status&sessionid=s74011&status=success"
  • The HTTP result code 200 "OK" is returned to OCC within HTTP request timeout periods indicating the connection and request to the IVR platform web service succeeded.
2016-10-11 12:00:52.106 [info] <0.289.0>@ivg_hvp_plugin:try_send_request:56 "V005D000000008911102016120049891" -> httpResult: {ok,{{"HTTP/1.1",200,"OK"},[{"date","Tue, 11 Oct 2016 16:00:49 GMT"},{"server","hcc/1.0"},{"content-length","17"},{"content-type","application/x-www-form-urlencoded"}],"session.id=s74011"}}
  • OCC receives an HTTP POST for the status of the attempted callback within the disposition timeout period.
2016-10-11 12:00:52.106 [info] <0.289.0>@callback:send_callback_request:172 "V005D000000008911102016120049891" -> Request successful, waiting for disposition timeout: 55000 milliseconds2016-10-11 12:00:57.656 [info] <0.251.0>@disposition_listener:handle_cast:64 Disposition Received. Method: 'POST', Path: "/vht/occ/V005D000000008911102016120049891", QueryStringData: [], Content-Type: "application/x-www-form-urlencoded", Body: "event=connected&name=status&sessionid=s74011&status=success"2016-10-11 12:00:57.656 [info] <0.289.0>@callback:response_received:96 "V005D000000008911102016120049891" -> Callback disposition received - Body: "event=connected&name=status&sessionid=s74011&status=success"

Search for "callback connected" to find callbacks that were successfully dialed in the occ.log files.

  • OCC parses and maps the body of the HTTP POST to a callback disposition for the VH CallID and informs QueueManager that the callback was successfully connected.
2016-10-11 12:00:57.656 [info] <0.289.0>@callback:log_disposition:228 "V005D000000008911102016120049891" -> Callback Disposition: {success,"Connected"}2016-10-11 12:00:57.656 [info] <0.289.0>@request_listener:set_data_value:318 "V005D000000008911102016120049891" -> QMCL Send - Set Data Value. DataValueName: "CallbackConnected". Value: "Callback Connected (via OCC)". DataValueNumber: 342.2016-10-11 12:00:57.656 [info] <0.289.0>@request_listener:set_data_value:320 "V005D000000008911102016120049891" -> QMCL Send - Set Data Value Request: <<"VHT_QMCL0710678000092<MsgId>137</MsgId><CallId>V005D000000008911102016120049891</CallId><DName>342</DName><DVal>Callback Connected (via OCC)</DVal><MakeRPC>0</MakeRPC>">>2016-10-11 12:00:57.656 [info] <0.289.0>@request_listener:set_data_value:324 "V005D000000008911102016120049891" -> QMCL Receive - Set Data Value Response: ok
  • OCC cleans up the VH CallID from its pending list of callbacks.
2016-10-11 12:00:57.656 [info] <0.289.0>@callback:terminate:138 "V005D000000008911102016120049891" -> Terminating callback process. Reason: normal2016-10-11 12:00:57.656 [info] <0.289.0>@callback:terminate:139 "V005D000000008911102016120049891" -> Call Cleanup - lookup CallId - confirm CallId removed2016-10-11 12:00:57.663 [info] <0.251.0>@disposition_listener:remove_pending_callback:230 "V005D000000008911102016120049891" -> Call Cleanup - CallId found. CallId removed

Starting and Stopping Erlang Application

Search "erlang_app" to locate stopping and starting erlang application logs.

Stopping

2016-10-11 12:00:00.097 [info] <0.176.0>@app_control_server:handle_call:61 stop_erlang_app: vht_outbound_contact_client

Starting

2016-10-11 12:00:09.195 [info] <0.176.0>@app_control_server:handle_call:64 start_erlang_app: vht_outbound_contact_client