Table of Contents

The HIS log is structured as a flat line based file. Each event starts on a new line and can span multiple lines based on the event type and content. Here’s an example event:

12023-06-13_14:59:39.445 UTC INFO PureCloudConversation PureCloud-rajat1.88102.88102.OM145908759400000001.c3fbc3cd-20c3-408a-b035-1a7d05322d91 - Object State: Conversation Member Added: sip:3e6406b6-c086-4482-b99f-fff74f9e0b88@127.0.0.1

An event has two major sections separated by <space> - <space>. The preamble section contains meta-data about the event including timestamp and level. The content section contains the actual event information. Let’s break down the example event into its sections.

Preamble Section

12023-06-13_14:59:39.445 UTC INFO PureCloudConversation PureCloud-rajat1.88102.88102.OM145908759400000001.c3fbc3cd-20c3-408a-b035-1a7d05322d91

The preamble section can be further divided into 4 data points: timestamp, level, source, and context.

Timestamp

Each event starts with a timestamp that records the time the event occurred at millisecond granularity. The timestamp format can be written as yyyy-MM-dd_hh:mm:ss.SSS Z in regex notation. This format is used to allow canonical comparison and sorting with values remaining in chronological order when in ascending order. The hour portion is written using the 24 hour clock (military time). The timezone of the event is the last portion and uses the standard 3 letter designation.

Level

Events can be one of 4 severities:

  • ERROR

  • WARN

  • INFO

  • DEBUG

The level always occupies 5 characters in the event with WARN and INFO being left aligned and having an extra <space> as padding. When setting log level, you chose the level to write which always includes the levels above that level. For instance setting the log level to INFO includes WARN and ERROR. Setting the level to ERROR will only generate ERROR level messages.

Source

The event source represents the internal component or object type that generated the event. The example event was generated by a PureCloudConversation object. This field does not contain <space>s to assist in parsing the event.

Context

The context field provides further details about the event source. Ownership information is provided in “dot” notation with each item owning the items that come after a '.'. The example event context provides the entire object hierarchy for the conversation:

  • PureCloud-rajat1 - The agent session id

  • 88102 - The channel group id

  • 88102 - The channel id

  • OM145908759400000001 - The interaction id

  • c3fbc3cd-20c3-408a-b035-1a7d05322d91 - The conversation id

The context field helps filter the log contents. For example you could see all the logs related to a particular agent session by searching for ‘PureCloud-rajat1’ since all logs, even those for child objects, will have a context field that starts with that value.

Content Section

1Object State: Conversation Member Added: sip:3e6406b6-c086-4482-b99f-fff74f9e0b88@127.0.0.1

The content section is a free-form area that contains details about the event. Although there is no standard structure to the content section, there are similarities between related events. The remainder of this document will have examples of important and common events.

Examples

System Startup

12023-06-13_14:58:24.351 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.avaya] 22023-06-13_14:58:24.351 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.genesys] 32023-06-13_14:58:24.351 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.incontact] 42023-06-13_14:58:24.352 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.incontact.hub] 52023-06-13_14:58:24.352 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.bridge] 62023-06-13_14:58:24.352 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.uccx] 72023-06-13_14:58:24.352 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.five9] 82023-06-13_14:58:24.352 UTC INFO ProcessorManagement - New processor factory [com.openmethods.ep.config.model.interactionprocessor.purecloud] 92023-06-13_14:58:24.352 UTC INFO ProcessorManagement - Activating processor management 102023-06-13_14:58:24.832 UTC INFO ProcessorManagement - Retrieving configuration from Config Server: https://cs.qa.openmethodscloud.com//work/v1/customers/348aa9f80e5647eb9223d06925ef7eb4/networkhosts/c4733e18-69f1-4708-b05a-a88d5aec1222/networkhostservices/ebaa72ce-b1ab-44aa-abcc-690363b57737/gethisconfig

When HIS starts up, it lists the types of telephony platforms the build supports. In the example, this is covered by the first 8 lines. Next it initializes the processor management component (line 9) and retrieves its configuration from Config Server (line 10). If you see these events, it means that HIS was restarted. Depending on the configuration provided by Config Server you will see one or more events:

12023-06-13_14:58:26.330 UTC INFO ProcessorManagement - Received service config: {"interactionProcessorId":"1736a3b1-dc32-4459-bc1d-3f156a318bde","interactionProcessorType":"com.openmethods.ep.config.model.interactionprocessor.avaya","extensions":[],"environment":{"environmentId":"61a7e295-5dd9-4658-84b1-ddfe8a892e2b","environmentName":"Avaya","environmentType":"com.openmethods.ep.config.model.environment.avaya","extensions":[{"namespace":"disposition.settings","data":{"dispositionEditable":false,"dispositionMaxLength":20,"dispositionRequired":false}},{"namespace":"environment.feature.settings","data":{"interactionDataEditable":true,"enableLogoutReasons":true,"ExternalQuickDial":false,"enableCountryCodes":false,"ForceAgentLogoutOnExit":false,"enableCallerId":false,"DisableSSO":false,"disableExternalNotReadyReasons":false,"AutoActivateChannels":false,"DisableAgentUpdate":false,"AgentSelectEditable":true,"enableDisposition":false,"enableCTIBridge":false}},{"namespace":"outbound.dial.rules","data":{"removeSpecialCharacters":false,"removeLeadingPlus":false,"removeLeading1":false,"dialPrefix":"","internationalDialPrefix":"","maxLength":40}},{"namespace":"avaya.environment.settings","data":{"TLinkName":"AVAYA#IBOMAVAYACM153#CSTA#IBOMAVAYAAES155","PrimaryAESPort":450,"ACWPollingTime":3000,"UUIFixedFormat":"","AESUser":"Tsapi_User","BackupAESAddress":"","UUIFormat":"URLEncoded","AESPassword":"Tsapi_User","PrimaryAESAddress":"192.168.28.155","AutoRetrieveEnabled":false,"BackupAESPort":450}},{"namespace":"agent.channel.settings","data":{"autoAnswerEmail":false,"autoAnswerPhone":false,"voicemail":false,"autoAnswerChat":false,"name":"","chat":true,"callbacks":false,"endCompletesInteraction":false,"email":true}}]}}

The json included in the event describes the processor configuration including its type "interactionProcessorType":"com.openmethods.ep.config.model.interactionprocessor.avaya", in this case Avaya. For each of these configurations, HIS will create a new processor component and initialize it. The initialization process can have minor differences depending on the platform type but they all follow a similar pattern.

12023-06-13_14:58:26.400 UTC INFO ProcessorManagement - Attempting to initiate processor: {"interactionProcessorId":"1736a3b1-dc32-4459-bc1d-3f156a318bde","interactionProcessorType":"com.openmethods.ep.config.model.interactionprocessor.avaya","extensions":[],"environment":{"environmentId":"61a7e295-5dd9-4658-84b1-ddfe8a892e2b","environmentName":"Avaya","environmentType":"com.openmethods.ep.config.model.environment.avaya","extensions":[{"namespace":"disposition.settings","data":{"dispositionEditable":false,"dispositionMaxLength":20,"dispositionRequired":false}},{"namespace":"environment.feature.settings","data":{"interactionDataEditable":true,"enableLogoutReasons":true,"ExternalQuickDial":false,"enableCountryCodes":false,"ForceAgentLogoutOnExit":false,"enableCallerId":false,"DisableSSO":false,"disableExternalNotReadyReasons":false,"AutoActivateChannels":false,"DisableAgentUpdate":false,"AgentSelectEditable":true,"enableDisposition":false,"enableCTIBridge":false}},{"namespace":"outbound.dial.rules","data":{"removeSpecialCharacters":false,"removeLeadingPlus":false,"removeLeading1":false,"dialPrefix":"","internationalDialPrefix":"","maxLength":40}},{"namespace":"avaya.environment.settings","data":{"TLinkName":"AVAYA#IBOMAVAYACM153#CSTA#IBOMAVAYAAES155","PrimaryAESPort":450,"ACWPollingTime":3000,"UUIFixedFormat":"","AESUser":"Tsapi_User","BackupAESAddress":"","UUIFormat":"URLEncoded","AESPassword":"Tsapi_User","PrimaryAESAddress":"192.168.28.155","AutoRetrieveEnabled":false,"BackupAESPort":450}},{"namespace":"agent.channel.settings","data":{"autoAnswerEmail":false,"autoAnswerPhone":false,"voicemail":false,"autoAnswerChat":false,"name":"","chat":true,"callbacks":false,"endCompletesInteraction":false,"email":true}}]}} 22023-06-13_14:58:26.568 UTC INFO AvayaProcessor Avaya - Starting plugin... 32023-06-13_14:58:26.571 UTC INFO AvayaProcessor Avaya - Starting Avaya JTAPI Plugin... 42023-06-13_14:58:26.573 UTC INFO AvayaProcessor Avaya - Connecting Avaya to AES: AVAYA#IBOMAVAYACM153#CSTA#IBOMAVAYAAES155;login=Tsapi_User;passwd=Tsapi_User;servers=192.168.28.155:450 52023-06-13_14:58:26.765 UTC INFO c.a.j.tsapi.impl.core.TSProviderImpl - TSProvider: version '7.0.0.64 [production build]', for TSProvider[#1]@1c058977

All processors regardless of type will start with a Starting plugin… event (line 2). Lines 3 & 4 are specific to the Avaya platform and indicate that the plugin is attempting to connect to AES. Line 5 is an example of the Avaya third-party library log events. For the most part these events can be ignored unless a very detailed review is needed to identify a product issue.

12023-06-13_14:58:27.683 UTC INFO AvayaProcessor Avaya - Plugin started.

Once a processor has successfully completed its initialization the above event will be generated. In the case of failure, a Plugin failed to start event is generated instead with further events that indicate the reason for failure.

Work Engine

HIS at its core is the middle-man between the agent’s media bar and the telephony platform. Requests and events can come from either side at any time. To ensure things are processed in the right order, HIS has a built in work engine component. New events or requests are added to a pair of work queues dedicated to the agent’s session; one for the media bar end and one for the telephony platform side. These queues produce debug log events as they process tasks:

12023-06-13_14:58:27.829 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.12778f90-8838-4779-ac73-99ad177cf085.inbound Size: 1 22023-06-13_14:58:27.829 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.12778f90-8838-4779-ac73-99ad177cf085.inbound 32023-06-13_14:58:27.829 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 42023-06-13_14:58:27.829 UTC DEBUG WorkEngine DirectClients.1 - Processing: media-bar rajat.gupta@openmethods.com.12778f90-8838-4779-ac73-99ad177cf085.inbound 1 52023-06-13_14:58:27.830 UTC DEBUG WorkEngine DirectClients.1 - Item: 0 Age: 0 InboundMessage: {"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 62023-06-13_14:58:27.830 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 7{"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 82023-06-13_14:58:27.832 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","service":{"id":"e70f36a4-982f-47e2-9420-780ebe581f36","name":"PureCloud","type":"com.openmethods.iserver.processor","serviceStatus":{"status":"Starting","acceptingClients":false,"clientCount":0},"info":{"vendor":"OpenMethods","version":"4.0.0","cti-vendor":"PureCloud","instance-domain":"PureCloud"}}} 92023-06-13_14:58:27.832 UTC DEBUG WorkEngine DirectClients.1 - Item 0 done in 3 InboundMessage: {"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 102023-06-13_14:58:27.832 UTC DEBUG WorkEngine DirectClients.1 - Finished with queue processing 112023-06-13_14:58:27.832 UTC DEBUG WorkEngine DirectClients.1 - Removing queue lock for media-bar rajat.gupta@openmethods.com.12778f90-8838-4779-ac73-99ad177cf085.inbound 122023-06-13_14:58:27.833 UTC DEBUG WorkEngine DirectClients.1 - Going back to idle pool 13

The first three lines are the work engine inspecting the media bar queue for tasks (line 1), dispatching the task to a worker thread (line 2), and then returning back to the thread pool. The remaining log entries are produced by the worker thread as it processes the task. Line 5 has important information related to task timing. The Age: value is the number of milliseconds the task has been waiting in queue. In the example, the task was picked up as soon as it was queued resulting in the 0 value. Lines 6 & 8 are log events generated by the task while being executed. Line 6 is also an example of a multiline event with Line 7 being the continuation of the event that starts on Line 6. Line 9 again provides additional timing information about how many milliseconds it took to complete the task. The last 3 lines are the worker thread cleaning up after the task and returning to the thread pool.

Agent Login

An agent login is probably the most complicated process handled by HIS and generates a large set of events.

12023-06-13_14:58:27.828 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 22023-06-13_14:58:27.830 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 3{"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 42023-06-13_14:58:27.832 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","service":{"id":"e70f36a4-982f-47e2-9420-780ebe581f36","name":"PureCloud","type":"com.openmethods.iserver.processor","serviceStatus":{"status":"Starting","acceptingClients":false,"clientCount":0},"info":{"vendor":"OpenMethods","version":"4.0.0","cti-vendor":"PureCloud","instance-domain":"PureCloud"}}}

When an agent logs into the media bar, the media bar first contacts all available HIS servers to get information about their current status and load. The status property indicates the general state of the processor. The acceptingClients property determines if the processor is currently accepting new clients. The clientCount property is the total number of clients that have bound to the service. The media bar uses this information to select the HIS that is accepting clients and has the lowest load (connected clients).

12023-06-13_14:58:33.218 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"messageType":"coreRequest","requestId":"56405ddd-0073-415c-9f55-9c9953831143","command":"bindService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 22023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 32023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 42023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 52023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients.1 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 62023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients.1 - Item: 0 Age: 0 InboundMessage: {"messageType":"coreRequest","requestId":"56405ddd-0073-415c-9f55-9c9953831143","command":"bindService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 72023-06-13_14:58:33.219 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 8{"messageType":"coreRequest","requestId":"56405ddd-0073-415c-9f55-9c9953831143","command":"bindService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 92023-06-13_14:58:33.219 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"56405ddd-0073-415c-9f55-9c9953831143","command":"bindService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","serviceName":"PureCloud","serviceType":"com.openmethods.iserver.processor","result":"success"} 102023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients.1 - Item 0 done in 0 InboundMessage: {"messageType":"coreRequest","requestId":"56405ddd-0073-415c-9f55-9c9953831143","command":"bindService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 112023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients.1 - Finished with queue processing 122023-06-13_14:58:33.219 UTC DEBUG WorkEngine DirectClients.1 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 132023-06-13_14:58:33.220 UTC DEBUG WorkEngine DirectClients.1 - Going back to idle pool 142023-06-13_14:58:33.323 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"messageType":"coreRequest","requestId":"140363ab-28ad-458b-b76f-f98130aec870","command":"bindService","serviceId":"WorkflowManager"} 152023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 162023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 172023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 182023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients.2 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 192023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients.2 - Item: 0 Age: 0 InboundMessage: {"messageType":"coreRequest","requestId":"140363ab-28ad-458b-b76f-f98130aec870","command":"bindService","serviceId":"WorkflowManager"} 202023-06-13_14:58:33.323 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 21{"messageType":"coreRequest","requestId":"140363ab-28ad-458b-b76f-f98130aec870","command":"bindService","serviceId":"WorkflowManager"} 222023-06-13_14:58:33.323 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"140363ab-28ad-458b-b76f-f98130aec870","command":"bindService","serviceId":"WorkflowManager","serviceName":"WorkflowManager","serviceType":"com.openmethods.iserver.workflow.manager","result":"success"} 232023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients.2 - Item 0 done in 0 InboundMessage: {"messageType":"coreRequest","requestId":"140363ab-28ad-458b-b76f-f98130aec870","command":"bindService","serviceId":"WorkflowManager"} 242023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients.2 - Finished with queue processing 252023-06-13_14:58:33.323 UTC DEBUG WorkEngine DirectClients.2 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 262023-06-13_14:58:33.324 UTC DEBUG WorkEngine DirectClients.2 - Going back to idle pool

Once an HIS instance is selected, the media bar binds to the processor and workflow components. Binding to a component allows a client to access that component’s API and receive events produced by it.

12023-06-13_14:58:34.699 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"requestId":"1062ccea-c1de-4d75-a2ed-f370d82a8df7","request":{"command":"getCapabilities","data":""},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 22023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 32023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 42023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 52023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients.3 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 62023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients.3 - Item: 0 Age: 0 InboundMessage: {"requestId":"1062ccea-c1de-4d75-a2ed-f370d82a8df7","request":{"command":"getCapabilities","data":""},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 72023-06-13_14:58:34.699 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 8{"requestId":"1062ccea-c1de-4d75-a2ed-f370d82a8df7","request":{"command":"getCapabilities","data":""},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 92023-06-13_14:58:34.699 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"serviceResponse","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","requestId":"1062ccea-c1de-4d75-a2ed-f370d82a8df7","response":{"command":"getCapabilities","result":"success","data":{"channel-groups-max-per-agent":"0","single-channels-media-types":"","channel-actions":"first","channel-groups-media-types":"","channel-groups-supported":"false","single-channels-supported":"true"}}} 102023-06-13_14:58:34.699 UTC DEBUG WorkEngine DirectClients.3 - Item 0 done in 0 InboundMessage: {"requestId":"1062ccea-c1de-4d75-a2ed-f370d82a8df7","request":{"command":"getCapabilities","data":""},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 112023-06-13_14:58:34.700 UTC DEBUG WorkEngine DirectClients.3 - Finished with queue processing 122023-06-13_14:58:34.700 UTC DEBUG WorkEngine DirectClients.3 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 132023-06-13_14:58:34.700 UTC DEBUG WorkEngine DirectClients.3 - Going back to idle pool 142023-06-13_14:58:34.762 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"requestId":"5b21f472-c7d2-41ae-91e2-a42813beeade","request":{"command":"prepareSession","data":{"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 152023-06-13_14:58:34.763 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 162023-06-13_14:58:34.763 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 172023-06-13_14:58:34.763 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 182023-06-13_14:58:34.763 UTC DEBUG WorkEngine DirectClients.5 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 192023-06-13_14:58:34.763 UTC DEBUG WorkEngine DirectClients.5 - Item: 0 Age: 0 InboundMessage: {"requestId":"5b21f472-c7d2-41ae-91e2-a42813beeade","request":{"command":"prepareSession","data":{"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 202023-06-13_14:58:34.763 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 21{"requestId":"5b21f472-c7d2-41ae-91e2-a42813beeade","request":{"command":"prepareSession","data":{"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 222023-06-13_14:58:34.763 UTC DEBUG PureCloudProcessor PureCloud - Looking for existing session to bind to client: PureCloud-rajat1 232023-06-13_14:58:34.763 UTC INFO PureCloudProcessor PureCloud - Creating new agent session with data {"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}. 242023-06-13_14:58:34.765 UTC INFO WorkflowManager SYSTEM - Created new workflow session PureCloud-rajat1 with model RNA-PureCloud 252023-06-13_14:58:34.765 UTC DEBUG WorkflowManager SYSTEM - Added session com.openmethods.iserver.workflow.WorkflowSession@3e33d97a to sessions. Total sessions: 2 262023-06-13_14:58:34.765 UTC DEBUG PureCloudProcessor PureCloud - Preauthenication is not possible for PureCloud 272023-06-13_14:58:34.765 UTC INFO PureCloudProcessor PureCloud - logging in agent rajat1 with properties {"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"} 282023-06-13_14:58:35.066 UTC DEBUG PureCloudAgent rajat1 - Initialized with processor com.openmethods.iserver.processor.purecloud.PureCloudProcessor@272c9f68 and ctiAgent rajat1 292023-06-13_14:58:35.066 UTC DEBUG PureCloudAgentSession PureCloud-rajat1 - initialized session for agent rajat1 302023-06-13_14:58:35.066 UTC DEBUG PureCloudAgentSession PureCloud-rajat1 - Added processor session listener com.openmethods.iserver.processor.purecloud.PureCloudProcessor@272c9f68. Total listeners: 1 312023-06-13_14:58:35.066 UTC DEBUG PureCloudProcessor PureCloud - added session PureCloud-rajat1 to {PureCloud-vishal=com.openmethods.iserver.processor.purecloud.PureCloudAgentSession@1c642be6, PureCloud-rajat1=com.openmethods.iserver.processor.purecloud.PureCloudAgentSession@56ac6195} 322023-06-13_14:58:35.066 UTC DEBUG PureCloudProcessor PureCloud - added session PureCloud-rajat1. Total sessions: 2 332023-06-13_14:58:35.066 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"serviceResponse","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","requestId":"5b21f472-c7d2-41ae-91e2-a42813beeade","response":{"command":"prepareSession","result":"success","resource":{"id":"PureCloud-rajat1"},"data":{"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}}} 342023-06-13_14:58:35.066 UTC DEBUG WorkEngine DirectClients.5 - Item 0 done in 303 InboundMessage: {"requestId":"5b21f472-c7d2-41ae-91e2-a42813beeade","request":{"command":"prepareSession","data":{"agent":{"id":"rajat1","password":"snu6XMUjEBstKXGhLkVQ0qvnGxQ3OwddLXgfobUpK2yW1Xql-b8uAf0nlJ4q4UpFowYCUUe1_UX6qHNdy8PP5w"},"model":"RNA-PureCloud","override":true,"cti":"e70f36a4-982f-47e2-9420-780ebe581f36"}},"messageType":"serviceRequest","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"} 352023-06-13_14:58:35.067 UTC DEBUG WorkEngine DirectClients.5 - Finished with queue processing 362023-06-13_14:58:35.067 UTC DEBUG WorkEngine DirectClients.5 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 372023-06-13_14:58:35.067 UTC DEBUG WorkEngine DirectClients.5 - Going back to idle pool

The media bar retrieves information from the processor component about its capabilities (lines 1-13). It then initiates a new agent session with the processor using the “prepareSession” command (line 14). The processor starts the process of logging the agent into the telephony platform.

12023-06-13_14:58:35.176 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"messageType":"coreRequest","requestId":"56475f8b-a24e-4d1d-8b2c-fc9281561a45","command":"bindResource","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","resourceId":"PureCloud-rajat1"} 22023-06-13_14:58:35.176 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 32023-06-13_14:58:35.176 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 42023-06-13_14:58:35.176 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 52023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 62023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Item: 0 Age: 1 InboundMessage: {"messageType":"coreRequest","requestId":"56475f8b-a24e-4d1d-8b2c-fc9281561a45","command":"bindResource","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","resourceId":"PureCloud-rajat1"} 72023-06-13_14:58:35.177 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 8{"messageType":"coreRequest","requestId":"56475f8b-a24e-4d1d-8b2c-fc9281561a45","command":"bindResource","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","resourceId":"PureCloud-rajat1"} 92023-06-13_14:58:35.177 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"56475f8b-a24e-4d1d-8b2c-fc9281561a45","command":"bindResource","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","resourceId":"PureCloud-rajat1","resourceName":"PureCloud-rajat1","resourceType":"com.openmethods.iserver.processor.session","result":"success"} 102023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Item 0 done in 0 InboundMessage: {"messageType":"coreRequest","requestId":"56475f8b-a24e-4d1d-8b2c-fc9281561a45","command":"bindResource","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36","resourceId":"PureCloud-rajat1"} 112023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Finished with queue processing 122023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 132023-06-13_14:58:35.177 UTC DEBUG WorkEngine DirectClients.1 - Going back to idle pool 142023-06-13_14:58:35.249 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Request Received: {"messageType":"coreRequest","requestId":"1b37e286-1d45-4e53-8d29-5ab8bdf51050","command":"bindResource","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1"} 152023-06-13_14:58:35.249 UTC DEBUG WorkEngine DirectClients - Inspecting Queue: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound Size: 1 162023-06-13_14:58:35.249 UTC DEBUG WorkEngine DirectClients - Dequeued 1 items from media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 172023-06-13_14:58:35.249 UTC DEBUG WorkEngine DirectClients - Looking for idle thread 182023-06-13_14:58:35.249 UTC DEBUG WorkEngine DirectClients.2 - Processing: media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 1 192023-06-13_14:58:35.250 UTC DEBUG WorkEngine DirectClients.2 - Item: 0 Age: 0 InboundMessage: {"messageType":"coreRequest","requestId":"1b37e286-1d45-4e53-8d29-5ab8bdf51050","command":"bindResource","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1"} 202023-06-13_14:58:35.250 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message: 21{"messageType":"coreRequest","requestId":"1b37e286-1d45-4e53-8d29-5ab8bdf51050","command":"bindResource","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1"} 222023-06-13_14:58:35.250 UTC INFO View initial - Entered State: initial 232023-06-13_14:58:35.250 UTC INFO WorkflowSession PureCloud-rajat1 - Client Event: state.updated 24{"messageType":"stateEvent","target":"PureCloud-rajat1","name":"state.updated","context":{},"data":[{"name":"session.logout","type":"disable"},{"name":"session.login","type":"enable"}]} 252023-06-13_14:58:35.250 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Response: {"messageType":"coreResponse","requestId":"1b37e286-1d45-4e53-8d29-5ab8bdf51050","command":"bindResource","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1","resourceName":"PureCloud-rajat1","resourceType":"com.openmethods.iserver.workflow.session","result":"success"} 262023-06-13_14:58:35.250 UTC DEBUG WorkEngine DirectClients.2 - Item 0 done in 1 InboundMessage: {"messageType":"coreRequest","requestId":"1b37e286-1d45-4e53-8d29-5ab8bdf51050","command":"bindResource","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1"} 272023-06-13_14:58:35.250 UTC DEBUG WorkEngine DirectClients.2 - Finished with queue processing 282023-06-13_14:58:35.250 UTC DEBUG WorkEngine DirectClients.2 - Removing queue lock for media-bar rajat.gupta@openmethods.com.9b5847bb-d944-4ac2-9eb5-ffb22b91df87.inbound 292023-06-13_14:58:35.250 UTC DEBUG WorkEngine DirectClients.2 - Going back to idle pool

As the session is created, a new processor session resource and workflow session resource are created and need to be bound to just like the processor and workflow services.

Workflow Events

12023-06-13_14:58:35.910 UTC INFO WorkflowSession PureCloud-rajat1 - Workflow Event: PureCloud-rajat1 session.started 22023-06-13_14:58:35.910 UTC DEBUG ViewObject session.PureCloud-rajat1 - processing event session.started 32023-06-13_14:58:35.910 UTC DEBUG ViewObject session.PureCloud-rajat1 - Found transition for event: session.started 42023-06-13_14:58:35.911 UTC INFO View initial - Exited State: initial 52023-06-13_14:58:35.911 UTC INFO View logged_in - Entered State: logged_in 62023-06-13_14:58:35.911 UTC DEBUG NetworkClient media-bar rajat.gupta@openmethods.com - Queued Event: {"messageType":"resourceEvent","serviceId":"WorkflowManager","resourceId":"PureCloud-rajat1","event":{"messageType":"stateEvent","target":"PureCloud-rajat1","name":"state.updated","context":{},"data":[{"name":"session.logout","type":"enable"},{"name":"session.login","type":"disable"}]}} 72023-06-13_14:58:35.911 UTC INFO WorkflowSession PureCloud-rajat1 - Client Event: state.updated 8{"messageType":"stateEvent","target":"PureCloud-rajat1","name":"state.updated","context":{},"data":[{"name":"session.logout","type":"enable"},{"name":"session.login","type":"disable"}]} 92023-06-13_14:58:35.911 UTC DEBUG WorkflowSession PureCloud-rajat1 - Done processing event: PureCloud-rajat1 session.started

As the session or interaction state changes, the workflow component keeps track using several state machines. An event is raised by the processor session and sent to the workflow engine (line 1). The workflow engine looks to see if there is a transition for the event and if there is changes the state machine (line 3). The state changes are listed in lines 3 & 4. When the state changes, the set of buttons or capabilities that are enabled and disable are updated and set to the client (lines 6-8).

Errors

12023-06-13_14:58:18.134 UTC ERROR MQProcessor CICEnvironment - Error reading messages. Resetting connection 2java.net.SocketException: Socket closed 3 at java.base/java.net.SocketInputStream.read(SocketInputStream.java:183) 4 at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140) 5 at java.base/java.net.SocketInputStream.read(SocketInputStream.java:200) 6 at com.openmethods.iserver.processor.cti.mq.MQProcessor$MessageListener.run(MQProcessor.java:490) 7 at java.base/java.lang.Thread.run(Thread.java:834)

Errors are almost always multi-line events. The first line contains information about the error and what was trying to be done when the error occurred. The remaining lines are a Java stack trace that provides technical details about the error and should be included in any bug report.