Transactions not being cancelled correctly

David Huang · ‎12-03-2015

Hi,

Was wondering if anyone has had an issue where a user may be using the instance as normal and then suddenly clicking on anything else stops working.

If you open a new tab it just stays as a blank screen.

This is due to the session appearing to still be doing something in the background when it is.

- No running transactions when looking at the transactions table

- putting "cancel_my_transactions.do" at the end of the page shows the last transaction being cancelled but that does not fix the issue

- Requires killing the browser process task to resolve the immediate issue

It's definitely that the session gets stuck in the browser but unsure what is causing it. Have tried to replicate it by doing the last steps the users were doing but didn't work.

Anyone got ideas?

These are the last lines in the logs from the session ID of an affected user:

Line 3921: 2015-12-03 08:43:45 (279) http-3 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47315 /xmlhttp.do

Line 3922: 2015-12-03 08:43:45 (280) http-2 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47316 /xmlhttp.do

Line 3923: 2015-12-03 08:43:45 (290) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 #47315 /xmlhttp.do Parameters -------------------------

Line 3956: 2015-12-03 08:43:47 (887) http-5 WARNING *** WARNING *** Transaction: Cancelling unclaimed (waiting) transaction #47316 /xmlhttp.do (cancelled by other transaction): Thread (huadav, 4524FEB9A800120021D6A7959C96E2E8), after 2607ms

Line 3958: 2015-12-03 08:43:47 (897) http-5 SYSTEM WARNING *** WARNING *** Transaction: Cancelling transaction #47315 /xmlhttp.do (cancelled by other transaction): Thread Default-thread-14 (huadav, 4524FEB9A800120021D6A7959C96E2E8), after 2618ms

Line 3963: 2015-12-03 08:43:47 (902) http-5 SYSTEM New transaction 4524FEB9A800120021D6A7959C96E2E8 #47317 /xmlhttp.do

Line 3965: 2015-12-03 08:43:47 (987) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Transaction cancelled: cancelled by other transaction

Line 4001: 2015-12-03 08:43:47 (995) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 #47315 /xmlhttp.do -- total transaction time: 0:00:02.716, total wait time: 0:00:00.001, session wait: 0:00:00.000, semaphore wait: 0:00:00.001, source: 10.128.82.187, 10.128.82.187

Line 4002: 2015-12-03 08:43:47 (996) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Connections active at session disconnect are being released

Line 4003: 2015-12-03 08:43:47 (996) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Validating and freeing unreleased connection 7

Line 4004: 2015-12-03 08:43:47 (996) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 isValid(): entered for connection 7

Line 4005: 2015-12-03 08:43:47 (998) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 isValid(): Connection 7 is valid

Line 4006: 2015-12-03 08:43:48 (009) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 #47317 /xmlhttp.do Parameters -------------------------

Line 4021: 2015-12-03 08:43:51 (206) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 Time: 0:00:01.802 id: dbUnityUAT1[glide.10] for: SELECT sys_user_group0."sys_id" FROM sys_user_group sys_user_group0 WHERE lower(sys_user_group0."name") LIKE lower(?) ESCAPE '\' AND (sys_user_group0."sys_id" IN ('c4b961c795c82100d0debe5efb5dcbd1' , 'c4b961c795c82100d0debe5efb5dcbd1' , '34b961c795c82100d0debe5efb5dcbf3' , '06596d8795c82100d0debe5efb5dcbb6' , '06596d8795c82100d0debe5efb5dcbb6' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , '72596d8795c82100d0debe5efb5dcbe7' , '4539e98795c82100d0debe5efb5dcb88' , '4539e98795c82100d0debe5efb5dcb88' , '5939e98795c82100d0debe5efb5dcb93' , '5939e98795c82100d0debe5efb5dcb93' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'ae8921c795c82100d0debe5efb5dcb6d' , 'ae8921c795c82100d0debe5efb5dcb6d' , '949921c795c82100d0debe5efb5dcbd0' , '949921c795c8...

Line 4022: 2015-12-03 08:43:51 (293) http-3 WARNING *** WARNING *** Transaction: Cancelling transaction #47317 /xmlhttp.do (cancelled by other transaction): Thread Default-thread-14 (huadav, 4524FEB9A800120021D6A7959C96E2E8), after 3392ms

Line 4027: 2015-12-03 08:43:51 (305) http-3 SYSTEM New transaction 4524FEB9A800120021D6A7959C96E2E8 #47318 /xmlhttp.do

Line 4028: 2015-12-03 08:43:51 (485) http-2 WARNING *** WARNING *** Transaction: Cancelling unclaimed (waiting) transaction #47318 /xmlhttp.do (cancelled by other transaction): Thread (huadav, 4524FEB9A800120021D6A7959C96E2E8), after 180ms

Line 4030: 2015-12-03 08:43:51 (497) http-2 SYSTEM New transaction 4524FEB9A800120021D6A7959C96E2E8 #47319 /xmlhttp.do

Line 4032: 2015-12-03 08:43:51 (537) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Transaction cancelled: cancelled by other transaction

Line 4068: 2015-12-03 08:43:51 (542) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 #47317 /xmlhttp.do -- total transaction time: 0:00:03.641, total wait time: 0:00:00.097, session wait: 0:00:00.097, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4069: 2015-12-03 08:43:51 (543) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Connections active at session disconnect are being released

Line 4070: 2015-12-03 08:43:51 (543) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Validating and freeing unreleased connection 0

Line 4071: 2015-12-03 08:43:51 (543) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 isValid(): entered for connection 0

Line 4072: 2015-12-03 08:43:51 (546) Default-thread-14 4524FEB9A800120021D6A7959C96E2E8 isValid(): Connection 0 is valid

Line 4073: 2015-12-03 08:43:51 (558) Default-thread-24 4524FEB9A800120021D6A7959C96E2E8 #47319 /xmlhttp.do Parameters -------------------------

Line 4088: 2015-12-03 08:43:51 (567) http-4 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47320 /xmlhttp.do

Line 4089: 2015-12-03 08:43:53 (367) Default-thread-24 4524FEB9A800120021D6A7959C96E2E8 Time: 0:00:00.214 id: dbUnityUAT1[glide.5] for: SELECT "sys_id" FROM (SELECT /*+ FIRST_ROWS(250) */ a.*, ROWNUM rnum FROM (SELECT sys_user_group0."sys_id" FROM sys_user_group sys_user_group0 WHERE lower(sys_user_group0."name") LIKE lower(?) ESCAPE '\' AND (sys_user_group0."sys_id" IN ('c4b961c795c82100d0debe5efb5dcbd1' , 'c4b961c795c82100d0debe5efb5dcbd1' , '34b961c795c82100d0debe5efb5dcbf3' , '06596d8795c82100d0debe5efb5dcbb6' , '06596d8795c82100d0debe5efb5dcbb6' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , '72596d8795c82100d0debe5efb5dcbe7' , '4539e98795c82100d0debe5efb5dcb88' , '4539e98795c82100d0debe5efb5dcb88' , '5939e98795c82100d0debe5efb5dcb93' , '5939e98795c82100d0debe5efb5dcb93' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'ae8921c795c82100d0debe5efb5dcb6d' , 'ae8921c795c8...

Line 4090: 2015-12-03 08:43:53 (369) Default-thread-24 4524FEB9A800120021D6A7959C96E2E8 #47319 /xmlhttp.do -- total transaction time: 0:00:01.872, total wait time: 0:00:00.049, session wait: 0:00:00.049, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4092: 2015-12-03 08:43:53 (383) Default-thread-6 4524FEB9A800120021D6A7959C96E2E8 #47320 /xmlhttp.do Parameters -------------------------

Line 4107: 2015-12-03 08:43:54 (981) Default-thread-6 4524FEB9A800120021D6A7959C96E2E8 Time: 0:00:00.213 id: dbUnityUAT1[glide.7] for: SELECT sys_user_group0."sys_id" FROM sys_user_group sys_user_group0 WHERE lower(sys_user_group0."name") LIKE lower(?) ESCAPE '\' AND (sys_user_group0."sys_id" IN ('c4b961c795c82100d0debe5efb5dcbd1' , 'c4b961c795c82100d0debe5efb5dcbd1' , '34b961c795c82100d0debe5efb5dcbf3' , '06596d8795c82100d0debe5efb5dcbb6' , '06596d8795c82100d0debe5efb5dcbb6' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , '72596d8795c82100d0debe5efb5dcbe7' , '4539e98795c82100d0debe5efb5dcb88' , '4539e98795c82100d0debe5efb5dcb88' , '5939e98795c82100d0debe5efb5dcb93' , '5939e98795c82100d0debe5efb5dcb93' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'ae8921c795c82100d0debe5efb5dcb6d' , 'ae8921c795c82100d0debe5efb5dcb6d' , '949921c795c82100d0debe5efb5dcbd0' , '949921c795c821...

Line 4112: 2015-12-03 08:43:58 (692) http-8 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47321 /xmlhttp.do

Line 4113: 2015-12-03 08:43:58 (707) http-1 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47322 /xmlhttp.do

Line 4114: 2015-12-03 08:43:59 (336) Default-thread-6 4524FEB9A800120021D6A7959C96E2E8 Time: 0:00:04.325 id: dbUnityUAT1[glide.10] for: SELECT "sys_id" FROM (SELECT /*+ FIRST_ROWS(250) */ a.*, ROWNUM rnum FROM (SELECT sys_user_group0."sys_id" FROM sys_user_group sys_user_group0 WHERE lower(sys_user_group0."name") LIKE lower(?) ESCAPE '\' AND (sys_user_group0."sys_id" IN ('c4b961c795c82100d0debe5efb5dcbd1' , 'c4b961c795c82100d0debe5efb5dcbd1' , '34b961c795c82100d0debe5efb5dcbf3' , '06596d8795c82100d0debe5efb5dcbb6' , '06596d8795c82100d0debe5efb5dcbb6' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , 'ba596d8795c82100d0debe5efb5dcbde' , '72596d8795c82100d0debe5efb5dcbe7' , '4539e98795c82100d0debe5efb5dcb88' , '4539e98795c82100d0debe5efb5dcb88' , '5939e98795c82100d0debe5efb5dcb93' , '5939e98795c82100d0debe5efb5dcb93' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'dd39e98795c82100d0debe5efb5dcb9c' , 'ae8921c795c82100d0debe5efb5dcb6d' , 'ae8921c795c8...

Line 4115: 2015-12-03 08:43:59 (405) Default-thread-6 4524FEB9A800120021D6A7959C96E2E8 #47320 /xmlhttp.do -- total transaction time: 0:00:07.839, total wait time: 0:00:01.802, session wait: 0:00:01.802, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4116: 2015-12-03 08:43:59 (418) Default-thread-18 4524FEB9A800120021D6A7959C96E2E8 #47321 /xmlhttp.do Parameters -------------------------

Line 4124: 2015-12-03 08:43:59 (441) Default-thread-18 4524FEB9A800120021D6A7959C96E2E8 #47321 /xmlhttp.do -- total transaction time: 0:00:00.749, total wait time: 0:00:00.713, session wait: 0:00:00.713, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4125: 2015-12-03 08:43:59 (449) Default-thread-21 4524FEB9A800120021D6A7959C96E2E8 #47322 /xmlhttp.do Parameters -------------------------

Line 4133: 2015-12-03 08:43:59 (465) Default-thread-21 4524FEB9A800120021D6A7959C96E2E8 #47322 /xmlhttp.do -- total transaction time: 0:00:00.758, total wait time: 0:00:00.734, session wait: 0:00:00.734, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4134: 2015-12-03 08:44:04 (452) http-3 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47323 /change_task.do

Line 4135: 2015-12-03 08:44:04 (466) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 #47323 /change_task.do Parameters -------------------------

Line 4227: 2015-12-03 08:44:04 (467) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 *** Start #47,323, path: /change_task.do, user: huadav

Line 4228: 2015-12-03 08:44:04 (494) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.change_request

Line 4229: 2015-12-03 08:44:04 (494) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.change_request.end_date

Line 4230: 2015-12-03 08:44:04 (495) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.change_request.start_date

Line 4231: 2015-12-03 08:44:04 (495) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.close_notes

Line 4232: 2015-12-03 08:44:04 (496) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.u_change_classification

Line 4233: 2015-12-03 08:44:04 (497) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.u_close_code

Line 4234: 2015-12-03 08:44:04 (497) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.u_close_sub_code

Line 4235: 2015-12-03 08:44:04 (499) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.u_std_msg_acknowledged

Line 4236: 2015-12-03 08:44:04 (500) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.work_end

Line 4237: 2015-12-03 08:44:04 (500) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 WARNING *** WARNING *** Security restricted: Access denied to set field change_task.work_start

Line 4239: 2015-12-03 08:44:04 (904) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 Memory transaction: 27mb total: 647mb free: 67% Allocated: 1,982mb

Line 4240: 2015-12-03 08:44:04 (904) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 *** End #47,323, path: /change_task.do, user: huadav, time: 0:00:00.452, render: 0:00:00.452, network: 0:00:00.000, chars: 114, SQL time: 152 (count: 59), business rule: 52 (count: 11)

Line 4241: 2015-12-03 08:44:04 (907) Default-thread-1 4524FEB9A800120021D6A7959C96E2E8 #47323 /change_task.do -- total transaction time: 0:00:00.455, total wait time: 0:00:00.000, session wait: 0:00:00.000, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4242: 2015-12-03 08:44:04 (947) http-8 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47324 /change_task.do

Line 4243: 2015-12-03 08:44:04 (955) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 #47324 /change_task.do Parameters -------------------------

Line 4248: 2015-12-03 08:44:04 (955) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 *** Start #47,324, path: /change_task.do, user: huadav

Line 4249: 2015-12-03 08:44:05 (309) http-9 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47325 /xmlhttp.do

Line 4250: 2015-12-03 08:44:05 (395) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 W2 invoke body: 0:00:00.403 ref: change_task

Line 4251: 2015-12-03 08:44:05 (413) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 Memory transaction: 28mb total: 676mb free: 66% Allocated: 1,982mb

Line 4252: 2015-12-03 08:44:05 (413) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 *** End #47,324, path: /change_task.do, user: huadav, time: 0:00:00.466, render: 0:00:00.463, network: 0:00:00.005, chars: 49,779, SQL time: 195 (count: 63), business rule: 12 (count: 3)

Line 4253: 2015-12-03 08:44:05 (415) Default-thread-3 4524FEB9A800120021D6A7959C96E2E8 #47324 /change_task.do -- total transaction time: 0:00:00.468, total wait time: 0:00:00.000, session wait: 0:00:00.000, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4254: 2015-12-03 08:44:05 (430) Default-thread-20 4524FEB9A800120021D6A7959C96E2E8 #47325 /xmlhttp.do Parameters -------------------------

Line 4261: 2015-12-03 08:44:05 (443) Default-thread-20 4524FEB9A800120021D6A7959C96E2E8 #47325 /xmlhttp.do -- total transaction time: 0:00:00.134, total wait time: 0:00:00.107, session wait: 0:00:00.107, semaphore wait: 0:00:00.000, source: 10.128.82.187, 10.128.82.187

Line 4262: 2015-12-03 08:44:06 (174) http-3 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47326 /data_table.do

Line 4285: 2015-12-03 08:44:06 (364) http-1 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47327 /data_table.do

Line 4286: 2015-12-03 08:44:06 (460) http-3 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47328 /xmlhttp.do

Line 4314: 2015-12-03 08:44:07 (563) http-2 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47329 /task_ci_list.do

Line 4332: 2015-12-03 08:44:18 (516) http-1 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47330 /task_ci_list.do

Line 4335: 2015-12-03 08:44:32 (171) http-1 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47331 /task_ci_list.do

Line 4368: 2015-12-03 08:44:44 (866) http-2 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47332 /task_ci_list.do

Line 4424: 2015-12-03 08:45:50 (201) http-2 New transaction 4524FEB9A800120021D6A7959C96E2E8 #47333 /task_ci_list.do

sergiu_panaite · ‎12-04-2015

Hi David,

If these transactions started (and it seems so based on your log), they must be visible in stats.do/threads.do, at least one of them, as they would need to reserve an http thread.

The only problem could be when the node is overloaded, and there are no available threads to reserve.

Have you checked the "Active Transactions" on that particular node where the user had the issue?

Regards,

Sergiu