Skip to end of metadata
Go to start of metadata

You are viewing an old version of this page. View the current version.

Compare with Current Restore this Version View Page History

« Previous Version 5 Next »

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:

2023-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

2023-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

Object 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.

System Startup

2023-06-13_14:58:24.351 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.avaya]
2023-06-13_14:58:24.351 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.genesys]
2023-06-13_14:58:24.351 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.incontact]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.incontact.hub]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.bridge]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.uccx]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.five9]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - New processor factory [com.openmethods.ep.config.model.interactionprocessor.purecloud]
2023-06-13_14:58:24.352 UTC INFO  ProcessorManagement  - Activating processor management
2023-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:

2023-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.

2023-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}}]}}
2023-06-13_14:58:26.568 UTC INFO  AvayaProcessor Avaya - Starting plugin...
2023-06-13_14:58:26.571 UTC INFO  AvayaProcessor Avaya - Starting Avaya JTAPI Plugin...
2023-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
2023-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.

2023-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:

2023-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
2023-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
2023-06-13_14:58:27.829 UTC DEBUG WorkEngine DirectClients - Looking for idle thread
2023-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
2023-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"}
2023-06-13_14:58:27.830 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message:
{"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"}
2023-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"}}}
2023-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"}
2023-06-13_14:58:27.832 UTC DEBUG WorkEngine DirectClients.1 - Finished with queue processing
2023-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
2023-06-13_14:58:27.833 UTC DEBUG WorkEngine DirectClients.1 - Going back to idle pool

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.

2023-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"}
2023-06-13_14:58:27.830 UTC DEBUG NetworkSession media-bar rajat.gupta@openmethods.com - Dispatching Message:
{"messageType":"coreRequest","requestId":"1bfc004b-386a-4ad6-a3aa-6c1a2a7f7adf","command":"getService","serviceId":"e70f36a4-982f-47e2-9420-780ebe581f36"}
2023-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).

This document may contain confidential and/or privileged information belonging to OpenMethods. If you are not the intended recipient (or have received this document in error) please notify the sender immediately and destroy this document. Any unauthorized copying, disclosure, or distribution of the material in this document is strictly forbidden.