Reading application logs

How to read logs with examples

๐Ÿšง

Logs from each applications are critical in successful debugging of any issues.

In 99% of support cases we require our customers to provide us a complete list of logs. Without them we are not able to perform any diagnostics!

๐Ÿ“˜

Check out common errors that appear in logs and fix issues on you own!

Please read page on logs troubleshooting and check if any of your issues may be fixed.

Where to find logs?

Every deployment has it's own configuration on logging. Contact your administrator to get access to log repository (eg. Grafana)

Nevertheless, if you have access to Kubernetes cluster you can always read logs with simple kubectl command.

admin@my-server ~
> $ kubectl get pods --all-namespaces
NAMESPACE            NAME                                                        READY   STATUS    RESTARTS        AGE
chatbots-app         admin-54945c395b-5nmqz                                      1/1     Running   0               30d
chatbots-app         analytics-6b5629758b-6hqhh                                  1/1     Running   0               30d
chatbots-app         channels-connector-625dd647d7-cs86x                         1/1     Running   0               30d
chatbots-app         cron-orchestrator-f56222bf5-sls78                           1/1     Running   0               30d
chatbots-app         dialogs-677bf22cc9-8nvtt                                    1/1     Running   0               30d
...
admin@my-server ~                                                                                                                                                                                                                                                                            [15:35:33]
> $ kubectl logs admin-54945c395b-5nmqz -n chatbots-app
05-24 13:36:06,997  INFO c.a.t.ConversationController:153 286f00a3c637e6a628c63b051c607e69 - [USER:777 IP:11.22.33.44 POST /api/conversations/details ConversationDetailsRequest(Some(),int_sid_20240524_39213410_3Qvasz4vkU,2024-05-24T12:53:33.000+02:00)
05-24 13:36:07,002  INFO p.c.b.SentiOneApiClient:61 286f00a3c637e6a628c63b051c607e69 - Calling API: POST https://chatbots-integration.sentione.com/api/bots/conversations/details
05-24 13:36:07,389  INFO p.c.b.SentiOneApiClient:56 286f00a3c637e6a628c63b051c607e69 - API call completed after 387ms
05-24 13:36:07,390  INFO c.a.a.AnalyticsApiClient:61 286f00a3c637e6a628c63b051c607e69 - Calling API: GET http://analytics:5754/session/int_sid_20240524_1234566_3Qvasz4vkU
05-24 13:36:07,394  INFO c.a.a.AnalyticsApiClient:56 286f00a3c637e6a628c63b051c607e69 - API call completed after 4ms
05-24 13:36:07,997  INFO c.a.t.ConversationController:153 9b9475ff762b06539be5ba8ae1b153eb - [USER:777 IP:11.22.33.44 POST /api/conversations/details ConversationDetailsRequest(Some(),int_sid_20240524_1234566_3Qvasz4vkU,2024-05-24T13:18:53.000+02:00)
05-24 13:36:08,002  INFO p.c.b.SentiOneApiClient:61 9b9475ff762b06539be5ba8ae1b153eb - Calling API: POST https://chatbots-integration.sentione.com/api/bots/conversations/details
05-24 13:36:08,322  INFO p.c.b.SentiOneApiClient:56 9b9475ff762b06539be5ba8ae1b153eb - API call completed after 320ms
05-24 13:36:08,322  INFO c.a.a.AnalyticsApiClient:61 9b9475ff762b06539be5ba8ae1b153eb - Calling API: GET http://analytics:5754/session/int_sid_20240524_1233453_T0lAm4yprh
05-24 13:36:08,326  INFO c.a.a.AnalyticsApiClient:56 9b9475ff762b06539be5ba8ae1b153eb - API call completed after 3ms
...

For more details please refer to official Kubernetes documentation.

๐Ÿ“˜

Do you want to simplify Kubernetes cluster management?

We recommend using k9s for easy access to cluster logs, configuration and much more without need to use kubectl command.


Log entry structure

<Date> <Time with ms> <Level> <Class with line number> <Request ID> <User details*> <Message>

Example entry:

07-26 09:00:46,176 INFO c.a.t.ConversationController:121 2e2f519aac523b8984cebb88427009b4 - [USER:777 IP:11.22.33.44 POST /api/conversations/details ConversationDetailsRequest(Some(),int_sid_20230725_50487038_6wx1Z8EiSh)

FieldExample
Date [month-day]07-26
Time [HH:mm:ss,SSS]09:00:46,176
Log levelINFO
Class with line numberc.c.a.ChannelsConnectorApiClient:61
Request id [uuid]2e2f519aac523b8984cebb88427009b4
User details - user ID and IP address (only available in admin app)USER:777 IP:11.22.33.44
Message (in admin app all user requests are logged)POST /api/conversations/details ConversationDetailsRequest(Some(),int_sid_20230725_50487038_6wx1Z8EiSh)

๐Ÿ‘ฎโ€โ™‚๏ธ

User accountability

In admin application all user requests are logged for security reasons.


Logging levels

Log levelDescription
DEBUGDetailed logs, used mainly for diagnostics (in the dialogs application this is the default logging level)
INFONormal logs, most logs are at this level, logs are very useful when investing, default logging level
WARNINGLess important, business error logs do not indicate an incorrect application state but rather incorrect user actions
ERRORApplication errors may result from connection errors, incorrect configuration or HTTP 500 responses from web services; do not always indicate a system failure, although their accumulation suggests a big problem

Example of security and other important events

If you are using external software to monitor IT security you may want to tap into following events:

Successful logging in

Application: admin

05-24 15:55:04,067 INFO c.AuthController:153 bcbaa960e00c797ffb497807e791892b - [AUTH] POST /login [****]
05-24 15:55:04,221 INFO c.AuthController:311 bcbaa960e00c797ffb497807e791892b - Logging user [email protected](777)
05-24 15:55:05,006 INFO c.a.SettingsController:153 edd5552e873d22fb89f01ccf46ac74f5 - [USER:777 IP:11.22.33.44 GET /api/settings


Unsuccessful login attempt

Application: admin

05-24 15:58:08,119 INFO c.AuthController:153 d7d31e9e4ece10802a1a0d94b99ae101 - [AUTH] GET /login
05-24 15:58:10,927 INFO c.AuthController:153 f97e31e614da9ad4e0aad3e1cc9e981b - [AUTH] POST /login [****]
05-24 15:58:10,932 INFO c.AuthController:134 f97e31e614da9ad4e0aad3e1cc9e981b - Unsuccessful attempt to log in as user admin
05-24 15:58:10,933 WARN f.ClientErrorLoggingFilter:18 f97e31e614da9ad4e0aad3e1cc9e981b - Client error, status 400 on POST /login, response: <...>


Anti brute-force triggered

Application: admin

05-24 16:02:42,158 INFO c.AuthController:153 403ad028f12f42892051152071f67482 - [AUTH] POST /login [****]
05-24 16:02:42,159 INFO c.AuthController:292 403ad028f12f42892051152071f67482 - 11.22.33.44 - User is not currently allowed to log in, because request was blocked by back-off mechanism
05-24 16:02:42,165 WARN f.ClientErrorLoggingFilter:18 403ad028f12f42892051152071f67482 - Client error, status 403 on POST /login, response: <...>


User entering system settings and confirming password

Application: admin

05-24 16:06:12,295 WARN f.ClientErrorLoggingFilter:18 cf09bf232d48d66f0091b6adea59d063 - Client error, status 401 on GET /api/checkPasswordConfirmation, response: Password confirmation required
05-24 16:06:15,925 INFO c.a.UserProfileController:153 a46469200a22c07bd17f66824cc56f97 - [USER:777 IP:11.22.33.44 POST /api/confirmPassword ConfirmPasswordModel(***)
05-24 16:06:16,081 INFO c.a.UserProfileController:91 a46469200a22c07bd17f66824cc56f97 - Password confirmation successful


Creating new user

Application: admin

05-24 16:08:14,898 INFO c.a.UserController:153 7ad005d0de7706ec72d9736272edd308 - [USER:777 IP:11.22.33.44 POST /api/users CreateUserModel([email protected], ***, 274, None)
05-24 16:08:14,998 INFO c.a.UserController:71 7ad005d0de7706ec72d9736272edd308 - Created user [email protected](655) with role Admin(274)


Deleting user

Application: admin

05-24 16:08:58,716 INFO c.a.UserController:153 06a730cc527020d5ed1af74e160b190f - [USER:777 IP:11.22.33.44 DELETE /api/users/655


Manipulating roles permissions

Application: admin

05-24 16:11:08,889 INFO c.a.RoleController:153 8a886d7d70db1f303381f174269d5f2d - [USER:777 IP:11.22.33.44 GET /api/roles
05-24 16:11:14,698 INFO c.a.RoleController:153 79c1e4d03e8aed3125318bc01ae6f15c - [USER:777 IP:11.22.33.44 POST /api/roles RoleModel(Analyst,Permissions(Off,Off,Off,Off,Off,Off,Off,Off,Off,Off,Off,Off,Off,Off))
05-24 16:11:14,796 INFO c.a.RoleController:153 d017f2ffab22c46760adadfad2214c54 - [USER:777 IP:11.22.33.44 GET /api/roles
05-24 16:11:18,848 INFO c.a.RoleController:153 0b61d5a07290a2945dddd954d72a07d9 - [USER:777 IP:11.22.33.44 PUT /api/roles/277 RoleModel(Analyst,Permissions(Off,Off,Read,Off,Off,Off,Off,On,On,Off,Off,Off,Off,Off))
05-24 16:11:18,949 INFO c.a.RoleController:153 dab287ead7646d9a13df0deb85361546 - [USER:777 IP:11.22.33.44 GET /api/roles


Generic deletions and modifications

Requests are made with DELETE HTTP method, whereas updates are made with PUT.

Application: admin

Deletion of entry in Knowledge base:

05-24 13:53:18,379 INFO c.a.KnowledgeBaseController:153 397eb3cba2a7538d7790afc6fa03e817 - [USER:777 IP:11.22.33.44 DELETE /api/knowledgeRecords/215895

Deletion of context in flow

05-24 14:04:11,640 INFO c.a.ContextController:153 ff84308a2b6b1ac9ba7514fb9c59dbce - [USER:777 IP:11.22.33.44 DELETE /api/projects/3338/flows/5132/contexts/57715

Delete NLU training phrase:

05-24 14:35:39,909 INFO c.a.PhraseController:153 ff3b9492063929db795cfe02d6ad6387 - [USER:777 IP:11.22.33.44 DELETE /api/projects/3341/nlus/9461/phrases/6145644

Update user settings or change organisation

05-24 16:10:36,101 INFO c.a.UserProfileController:153 f298429e7e05eb04f23cdaa5a4dbeb23 - [USER:777 IP:11.22.33.44 PUT /api/userProfile UpdateUserProfileRequest(en,777,false)


Publish new version of flow

Application: admin

05-24 16:18:30,499 INFO c.a.FlowVersionController:153 e377c4835f348968b2cb586f589ec89e - [USER:777 IP:11.22.33.44 POST /api/projects/3154/flows/4859/versions FlowVersionModel(None)
05-24 16:18:30,515 INFO s.DialogManagerService:147 e377c4835f348968b2cb586f589ec89e - Validating dialog 4b7f617e-3a54-44a5-a275-7447cdace5fa...
05-24 16:18:30,590 INFO c.a.FlowVersionController:153 7450b61e62bf462f8da035f7eab09165 - [USER:777 IP:11.22.33.44 POST /api/projects/3154/flows/4859/versions/15703/publish
05-24 16:18:30,604 INFO s.DialogManagerService:147 7450b61e62bf462f8da035f7eab09165 - Validating dialog 4b7f617e-3a54-44a5-a275-7447cdace5fa...
05-24 16:18:30,615 INFO c.d.a.DialogManagerApiClient:61 7450b61e62bf462f8da035f7eab09165 - Calling API: POST http://dialogs:5748/publish
05-24 16:18:30,622 INFO c.d.a.DialogManagerApiClient:56 7450b61e62bf462f8da035f7eab09165 - API call completed after 7ms
05-24 16:18:30,629 INFO s.w.WebsocketServiceImpl:33 7450b61e62bf462f8da035f7eab09165 - Broadcasting PublishFlowVersionSuccess to company 131 (1 sessions)


Training NLU

Application: admin

05-24 16:19:41,993 INFO c.a.NluApiController:153 3ca37450d9f2282b70d8f2a4dc86938f - [USER:777 IP:11.22.33.44 GET /api/projects/3154/nlus/9099/train
05-24 16:19:42,001 INFO s.n.NluTrainService:41 3ca37450d9f2282b70d8f2a4dc86938f - Adding NLU train request to queue for model id=55ca2c05-4865-4578-ae30-c891d884c5cc, seed=None, modelType=Simple
05-24 16:19:42,008 INFO s.w.WebsocketServiceImpl:33 3ca37450d9f2282b70d8f2a4dc86938f - Broadcasting NluStatusChanged to company 131 (1 sessions)
05-24 16:19:42,008 INFO s.w.WebsocketServiceImpl:45 3ca37450d9f2282b70d8f2a4dc86938f - Broadcasting NluTrainQueueChanged to everyone (6 sessions)
05-24 16:19:42,024 INFO s.n.NluTrainService:78 3ca37450d9f2282b70d8f2a4dc86938f - Staring training for Ask with id 9099. Current queue size: 1
05-24 16:19:42,027 INFO s.w.WebsocketServiceImpl:33 3ca37450d9f2282b70d8f2a4dc86938f - Broadcasting NluStatusChanged to company 131 (1 sessions)
05-24 16:19:42,027 INFO s.w.WebsocketServiceImpl:45 3ca37450d9f2282b70d8f2a4dc86938f - Broadcasting NluTrainQueueChanged to everyone (6 sessions)


Calling REST Integration in the bot runtime

Application: dialogs

05-24 16:24:11,318 INFO c.d.e.i.IntegrationServiceImpl:34 webchat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Executing integration 9466661c-f899-4573-b963-cbefb88439e4, request bdae9869-0aac-4906-923d-cd80383ff5ac
05-24 16:24:11,318 INFO c.d.e.i.IntegrationServiceImpl:35 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Received input parameters Map(PARCEL_NUMBER -> StringValue(653699790080))
05-24 16:24:11,322 INFO c.i.IntegrationRequestBuilder:29 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Building request from model: IntegrationRequest(bdae9869-0aac-4906-923d-cd80383ff5ac,Get parcel status,shipx-proxy/,Get,Some(),Map(),Map(number -> 653699790080),HashMap(coordinates -> custom_attributes.target_machine_detail.location, parcel_status -> status, location_description -> custom_attributes.target_machine_detail.location_description, address_line1 -> custom_attributes.target_machine_detail.address.line1, target_machine_id -> custom_attributes.target_machine_id, address_line2 -> custom_attributes.target_machine_detail.address.line2),Map(0 -> PARCEL_NUMBER),Raw,false,None)
05-24 16:24:11,322 INFO c.i.IntegrationRequestBuilder:68 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Preparing header AuthHeader(Plain,User-Agent,Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0)
05-24 16:24:11,322 INFO c.i.IntegrationRequestBuilder:68 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Preparing header AuthHeader(Plain,Accept,
/)
05-24 16:24:11,322 INFO c.i.IntegrationRequestBuilder:68 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Preparing header AuthHeader(Plain,Accept-Language,pl,en;q=0.7,en-US;q=0.3)
05-24 16:24:11,322 INFO c.i.IntegrationRequestBuilder:68 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Preparing header AuthHeader(Plain,X-Requested-With,XMLHttpRequest)
05-24 16:24:11,322 INFO c.i.IntegrationRequestExecutor:43 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Performing request: Request(method=GET, uri=https://inpost.pl/shipx-proxy/?number=653699790080, httpVersion=HTTP/1.1, headers=Headers(User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:124.0) Gecko/20100101 Firefox/124.0, Accept:
/_, Accept-Language: pl,en;q=0.7,en-US;q=0.3, X-Requested-With: XMLHttpRequest))
05-24 16:24:11,323 INFO c.i.IntegrationClient:61 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Calling API: GET https://inpost.pl/shipx-proxy/?number=653699790080
05-24 16:24:11,689 INFO c.i.IntegrationRequestExecutor:45 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Response: Response(status=200, httpVersion=HTTP/1.1, headers=Headers(Date: Fri, 24 May 2024 14:24:11 GMT, Content-Type: application/json, Transfer-Encoding: chunked, Connection: keep-alive, X-Content-Type-Options: nosniff, Vary: Accept-Encoding, Server-Timing: dtSInfo;desc="1", Set-Cookie: , Strict-Transport-Security: max-age=16070400; includeSubDomains; preload, X-XSS-Protection: 1; mode=block, Access-Control-Allow-Origin: *, CF-Cache-Status: DYNAMIC, Set-Cookie: , Set-Cookie: , Server: cloudflare, CF-RAY: 888df2a848b08d83-HEL, alt-svc: h3=":443"; ma=86400))
05-24 16:24:11,690 INFO c.i.IntegrationRequestExecutor:47 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - Body: {"tracking_number":"653699790080","service":"inpost_locker_standard","type":"inpost_locker_standard",
...
{"origin_status":"PPN","status":"confirmed","agency":null,"location":null,"datetime":"2024-04-28T05:50:10.000+02:00"}],"expected_flow":[],"created_at":"2024-04-28T05:50:10.024+02:00","updated_at":"2024-04-30T20:39:23.440+02:00"}
05-24 16:24:11,696 INFO c.i.IntegrationClient:56 web_chat_202405241622_rPUdKljHkx_31bf101ee49ed3b1b7d968d6a66f759f - API call completed after 373ms