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
kubectlcommand.
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)
| Field | Example |
|---|---|
| Date [month-day] | 07-26 |
| Time [HH:mm:ss,SSS] | 09:00:46,176 |
| Log level | INFO |
| Class with line number | c.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 level | Description |
|---|---|
| DEBUG | Detailed logs, used mainly for diagnostics (in the dialogs application this is the default logging level) |
| INFO | Normal logs, most logs are at this level, logs are very useful when investing, default logging level |
| WARNING | Less important, business error logs do not indicate an incorrect application state but rather incorrect user actions |
| ERROR | Application 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 - [IP:11.22.33.44] 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 - [IP:11.22.33.44] User admin 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: <...>
Logging out
Application: admin
07-15 11:50:53,029 INFO c.AuthController:158 dc63acb62519604ed8176f173b9a66e7 - [AUTH] GET /logout
07-15 11:50:53,029 INFO c.AuthController:246 dc63acb62519604ed8176f173b9a66e7 - [IP:11.22.33.44] User admin is logging out
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
Updated 4 months ago