Job unexpectedly terminates early - UBRQ_SETSTOP Command in classic appserver broker log

P

progress_siva

New Member
Hello everyone,


I'm working with an application running on Progress 11.7.17 Classic AppServer in state-free mode (yes, I know it's outdated — sorry!).


I'm currently troubleshooting an intermittent issue where a submitted job unexpectedly terminates early. The only consistent clue I've found so far is the following pattern in the logs whenever the issue occurs:


In the broker log:
P-028468 T-C-0011 3 UB Basic Enqueued request UBRQ_SETSTOP issued to S-0047 requestID= <none>


And in the agent log:
P-006224 T-019936 3 AS AS -- TRACE: Non-PERSISTENT Procedure END STOP. (8397)


Has anyone encountered something similar? Any suggestions or guidance on where to look or how to proceed with debugging this would be greatly appreciated.


Thanks in advance!
 
Could you post an extract from broker, agent and DB log around the time of the job terminating please, rather than single lines. Some of the more experienced hands might be able to spot something you haven't. Single lines like this could just be red herrings.
 
Thanks for the response!
Below is a more detailed excerpt from the logs (elevated logging was enabled):
The lines highlighted in bold in both the broker and agent logs consistently appear whenever this issue occurs.

Broker Log :
Code: 
25/06/16@08:06:49.219-0700] P-028468 T-C-0030 2 UB Basic      ConnectionID= 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b3e. (8096)
[25/06/16@08:06:49.219-0700] P-028468 T-C-0030 2 UB Basic      Client connected : 10.232.30.165. (8533)
[25/06/16@08:06:49.219-0700] P-028468 T-C-0030 2 UB Basic      The client requested ASK version= 1.0  capabilities= allowServerASK,allowClientASK. (13769)
[25/06/16@08:06:49.219-0700] P-028468 T-C-0030 2 UB Basic      The negotiated ASK version= 1.0  capabilities= denyServerASK,denyClientASK.  ASK protocol is disabled for this connection. (15256)
[25/06/16@08:06:49.222-0700] P-028468 T-C-0030 3 UB Basic      Enqueued request UBRQ_INIT_RQ issued to S-0043 requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000429>
[25/06/16@08:06:49.223-0700] P-028468 T-C-0030 3 UB Basic      Enqueued request UBRQ_WRITEDATALAST issued to S-0043 requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000429>
[25/06/16@08:06:49.223-0700] P-028468 T-C-0030 3 UB Basic      Request for 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b3e issued to S-0043. (8535)
[25/06/16@08:06:49.487-0700] P-028468 T-C-0012 2 UB Basic      Client disconnected : 10.232.30.165. (8534)
[25/06/16@08:06:49.619-0700] P-028468 T-C-0030 2 UB Basic      Client disconnected : 10.232.30.165. (8534)
[25/06/16@08:06:49.830-0700] P-028468 T-C-0028 2 UB Basic      Client disconnected : 10.232.20.30. (8534)
[25/06/16@08:06:49.953-0700] P-028468 T-L-30420 3 UB Basic      Got a connection:: (8125)
[25/06/16@08:06:49.953-0700] P-028468 T-C-0023 2 UB Basic      ConnectionID= 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b3f. (8096)
[25/06/16@08:06:49.953-0700] P-028468 T-C-0023 2 UB Basic      Client connected : 10.232.20.30. (8533)
[25/06/16@08:06:49.953-0700] P-028468 T-C-0023 2 UB Basic      The client requested ASK version= 1.0  capabilities= denyClientASK,allowServerASK. (13769)
[25/06/16@08:06:49.953-0700] P-028468 T-C-0023 2 UB Basic      The negotiated ASK version= 1.0  capabilities= denyServerASK,denyClientASK.  ASK protocol is disabled for this connection. (15256)
[25/06/16@08:06:49.955-0700] P-028468 T-C-0023 3 UB Basic      Enqueued request UBRQ_INIT_RQ issued to S-0044 requestID= 2+EFLExnCZjbFLdTdQiAHQ
[25/06/16@08:06:49.955-0700] P-028468 T-C-0023 3 UB Basic      Enqueued request UBRQ_WRITEDATALAST issued to S-0044 requestID= 2+EFLExnCZjbFLdTdQiAHQ
[25/06/16@08:06:49.955-0700] P-028468 T-C-0023 3 UB Basic      Request for 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b3f issued to S-0044. (8535)
[25/06/16@08:06:50.506-0700] P-028468 T-C-0023 2 UB Basic      Client disconnected : 10.232.20.30. (8534)
[25/06/16@08:06:50.915-0700] P-028468 T-C-0011 3 UB Basic      Enqueued request UBRQ_SETSTOP issued to S-0047 requestID= <none>
[25/06/16@08:06:51.078-0700] P-028468 T-L-30420 3 UB Basic      Got a connection:: (8125)
[25/06/16@08:06:51.080-0700] P-028468 T-C-0016 2 UB Basic      ConnectionID= 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b40. (8096)
[25/06/16@08:06:51.081-0700] P-028468 T-C-0016 2 UB Basic      Client connected : 10.232.30.165. (8533)
[25/06/16@08:06:51.081-0700] P-028468 T-C-0016 2 UB Basic      The client requested ASK version= 1.0  capabilities= allowServerASK,allowClientASK. (13769)
[25/06/16@08:06:51.081-0700] P-028468 T-C-0016 2 UB Basic      The negotiated ASK version= 1.0  capabilities= denyServerASK,denyClientASK.  ASK protocol is disabled for this connection. (15256)
[25/06/16@08:06:51.083-0700] P-028468 T-C-0016 3 UB Basic      Enqueued request UBRQ_INIT_RQ issued to S-0045 requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000431>
[25/06/16@08:06:51.083-0700] P-028468 T-C-0016 3 UB Basic      Enqueued request UBRQ_WRITEDATALAST issued to S-0045 requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000431>
[25/06/16@08:06:51.083-0700] P-028468 T-C-0016 3 UB Basic      Request for 10.232.20.112::asactivecareservices_A00507::30420::99e53be61571296e:570760b8:1977730935e:4b40 issued to S-0045. (8535)
[25/06/16@08:06:51.325-0700] P-028468 T-C-0016 2 UB Basic      Client disconnected : 10.232.30.165. (8534)
Agent Log :
Code: 
[25/06/16@08:06:49.223-0700] P-017292 T-024684 3 AS AS requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000429>
[25/06/16@08:06:49.223-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/wxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:06:49.483-0700] P-026352 T-001172 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:06:49.606-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:06:49.827-0700] P-015156 T-030768 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:06:49.955-0700] P-013336 T-012136 3 AS AS requestID= 2+EFLExnCZjbFLdTdQiAHQ
[25/06/16@08:06:49.956-0700] P-013336 T-012136 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'as/Service/sns/UpdateNotificationSNSDeliveryStatus.p' START. (5498)
[25/06/16@08:06:50.504-0700] P-013336 T-012136 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:06:51.083-0700] P-026352 T-001172 3 AS AS requestID= <REQ|Z/NzQ4/jTKiiFXPumTGVOw|00000431>
[25/06/16@08:06:51.083-0700] P-026352 T-001172 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/wxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:06:51.322-0700] P-026352 T-001172 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:06:51.436-0700] P-006224 T-019936 1 AS -- (Procedure: 'initializeObject as/Service/emp/GetAvailEmployeeExt.p' Line:2210) QUICKBIDINVITEDEBUG - GetAvailEmployeeExt.p - calling FilterEmployeesESG
[25/06/16@08:06:51.476-0700] P-006224 T-019936 1 AS -- (Procedure: 'initializeObject as/Service/emp/GetAvailEmployeeExt.p' Line:2105) QUICKBIDINVITEDEBUG - GetAvailEmployeeExt.p - calling GetAvailEmployee.p
[25/06/16@08:06:53.917-0700] P-006224 T-019936 3 AS AS -- TRACE: Non-PERSISTENT Procedure END STOP. (8397)
[25/06/16@08:06:54.723-0700] P-017292 T-024684 3 AS AS requestID= <REQ|7HguJr//R+mV8eadkUdBqg|00000075>
[25/06/16@08:06:54.723-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/wxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:06:55.000-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:07:35.385-0700] P-015156 T-030768 3 AS AS requestID= <REQ|a51i2JyQkUWgO0v2ZehyJA-00000784>
[25/06/16@08:07:35.386-0700] P-015156 T-030768 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/etxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:07:35.388-0700] P-015156 T-030768 1 AS -- (Procedure: 'sys/etxRequestHandlerJSON.p' Line:198) pcSessionID error 1670:  ping_client.net
[25/06/16@08:07:35.388-0700] P-015156 T-030768 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:07:42.051-0700] P-013336 T-012136 3 AS AS requestID= <REQ|fow95JdZSA+c4cq2o5HW2g|00000178>
[25/06/16@08:07:42.051-0700] P-013336 T-012136 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/etxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:07:42.066-0700] P-013336 T-012136 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
[25/06/16@08:07:44.126-0700] P-026352 T-001172 3 AS AS requestID= <REQ|fg12TdhFTWqb7AmMgzlQ4A|00000205>
[25/06/16@08:07:44.127-0700] P-026352 T-001172 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/wxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:07:44.133-0700] P-006224 T-019936 3 AS AS requestID= <REQ|fWaLovIYRmCtiq7qEVgS0g|00000522>
[25/06/16@08:07:44.134-0700] P-006224 T-019936 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'sys/wxRequestHandlerJSON.p' START. (5498)
[25/06/16@08:07:44.144-0700] P-017292 T-024684 3 AS AS requestID= <REQ|7HguJr//R+mV8eadkUdBqg|00000116>
[25/06/16@08:07:44.144-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure 'as/Service/sys/ValidateSessionID.p' START. (5498)
[25/06/16@08:07:44.148-0700] P-017292 T-024684 3 AS AS -- TRACE: Non-PERSISTENT Procedure END SUCCESS. (8397)
DB Log :
Code: 
[2025/06/16@07:50:25.098-0700] P-17292      T-24684 I APPSRV 17: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3537 to 3978.
[2025/06/16@07:57:45.615-0700] P-15156      T-30768 I APPSRV 19: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3096 to 3537.
[2025/06/16@07:57:45.624-0700] P-15156      T-30768 I APPSRV 19: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3537 to 3978.
[2025/06/16@08:03:03.171-0700] P-15336      T-23676 I SRV     2: (794)   Usernum 170 terminated abnormally.
[2025/06/16@08:03:03.172-0700] P-15336      T-23676 I SRV     2: (739)   Logout usernum 170, userid , on prodv3moxa1a.
[2025/06/16@08:05:32.525-0700] P-26352      T-1172  I APPSRV 18: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3537 to 3978.
[2025/06/16@08:08:00.253-0700] P-6224       T-19936 I APPSRV 20: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3096 to 3537.
[2025/06/16@08:08:00.261-0700] P-6224       T-19936 I APPSRV 20: (5409)  WARNING: -mmax exceeded. Automatically increasing from 3537 to 3978.
[2025/06/16@08:14:12.600-0700] P-17292      T-24684 I APPSRV 17: (7129)  Usr 17 set name to Dark.
 
Last edited by a moderator:
You must log in or register to reply here.
Back
Top