"job closed" entries not logged in TIBCO Spotfire Server sql.log after executing any Information Link

"job closed" entries not logged in TIBCO Spotfire Server sql.log after executing any Information Link

After successful execution of an Information Link, the ‘job closed’ entries in TIBCO Spotfire Server sql.log provide information about the total time the query took from query execution until the client has received all the result data. This information helps when troubleshooting performance issues with the information links. For more information on this, refer section "Identify Information Link execution in sql.log”  in KB Troubleshooting Guide: Performance issues with Information Links.

However in the sql.log (<Spotfire server installation>\tomcat\logs) you may see those "job closed" entries are not getting logged at all.

For example, in these log entries, the "job closed" entry does not get logged after executing information link 'USERS':

2020-04-02T07:03:57,626+0530 [*pool-12-thread-1, boston\demo_user, #3, #6599*]: Executing Information Link 'USERS' (01ea968e-2de6-458c-9bae-00f2b388db6e):
Columns:
  USER_ID (eade3988-fe22-454c-93be-9bc65b6dbe7b)
  USER_NAME (fee6f972-87bb-4a06-b390-6a3b173caec3)
  DOMAIN_NAME (019b9ced-fe1a-4a8b-8c63-9dfffd5bf2d5)
  EXTERNAL_ID (76aaf0b3-9273-4671-81d3-5eb15c5bf2c8)
  PRIMARY_GROUP_ID (39141a36-62b5-4910-8408-5f53e9a6f31f)
  LAST_MODIFIED_MEMBERSHIP (b3d5dc74-8714-462f-b106-40a4b4dec780)
  PASSWORD (10f41856-7335-4898-8138-663574b63efe)
  DISPLAY_NAME (94308824-30aa-474f-830d-2e7e279625dd)
  EMAIL (b18c3290-9982-4843-bb02-0f0e86718b44)
  ENABLED (9cdbd3f4-6394-483c-a8f1-851192346ff3)
  LOCKED_UNTIL (fef6e6a3-2807-4cf9-92cf-9260e2330ce3)
  LAST_LOGIN (53bbc983-f788-436c-941d-2c312bbb1aea)

2020-04-02T07:03:57,642+0530 [*pool-12-thread-1, boston\demo_user, #3, #6599*]: [data-source="Test_DataSource"] 
SELECT
   U1."USER_ID" AS "USERID",
   U1."USER_NAME" AS "USERNAME",
   U1."DOMAIN_NAME" AS "DOMAINNAME",
   U1."EXTERNAL_ID" AS "EXTERNALID",
   U1."PRIMARY_GROUP_ID" AS "PRIMARYGROUPID",
   U1."LAST_MODIFIED_MEMBERSHIP" AS "LASTMODIFIEDMEMBERSHIP",
   U1."PASSWORD" AS "PASSWORD",
   U1."DISPLAY_NAME" AS "DISPLAYNAME",
   U1."EMAIL" AS "EMAIL",
   U1."ENABLED" AS "ENABLED",
   U1."LOCKED_UNTIL" AS "LOCKEDUNTIL",
   U1."LAST_LOGIN" AS "LASTLOGIN"
FROM
   "spotfire_server_1033"."dbo"."USERS" U1

2020-04-02T07:03:57,922+0530 [*pool-12-thread-2, boston\demo_user, #3, #6599*]: Information Link 'USERS' (01ea968e-2de6-458c-9bae-00f2b388db6e) executed successfully, time: 0.296 seconds
  The “job closed” entries in sql.log are getting captured only when TIBCO Spotfire Server logs are captured in DEBUG mode. To resolve, enable DEBUG logging on the TIBCO Spotfire Server per Changing server and node logging levels. The note is mentioned on Server and node logging levels reference.

Here are some example logs with Spotfire Server DEBUG logging enabled where "job closed" entry gets logged after executing same information link  'USERS': 

2020-04-02T07:07:40,854+0530 [*pool-12-thread-3, boston\demo_user, #3, #6650*]: Executing Information Link 'USERS' (01ea968e-2de6-458c-9bae-00f2b388db6e):
Columns:
  USER_ID (eade3988-fe22-454c-93be-9bc65b6dbe7b)
  USER_NAME (fee6f972-87bb-4a06-b390-6a3b173caec3)
  DOMAIN_NAME (019b9ced-fe1a-4a8b-8c63-9dfffd5bf2d5)
  EXTERNAL_ID (76aaf0b3-9273-4671-81d3-5eb15c5bf2c8)
  PRIMARY_GROUP_ID (39141a36-62b5-4910-8408-5f53e9a6f31f)
  LAST_MODIFIED_MEMBERSHIP (b3d5dc74-8714-462f-b106-40a4b4dec780)
  PASSWORD (10f41856-7335-4898-8138-663574b63efe)
  DISPLAY_NAME (94308824-30aa-474f-830d-2e7e279625dd)
  EMAIL (b18c3290-9982-4843-bb02-0f0e86718b44)
  ENABLED (9cdbd3f4-6394-483c-a8f1-851192346ff3)
  LOCKED_UNTIL (fef6e6a3-2807-4cf9-92cf-9260e2330ce3)
  LAST_LOGIN (53bbc983-f788-436c-941d-2c312bbb1aea)

2020-04-02T07:07:40,854+0530 [*pool-12-thread-3, boston\demo_user, #3, #6650*]: [data-source="Test_DataSource"] 
SELECT
   U1."USER_ID" AS "USERID",
   U1."USER_NAME" AS "USERNAME",
   U1."DOMAIN_NAME" AS "DOMAINNAME",
   U1."EXTERNAL_ID" AS "EXTERNALID",
   U1."PRIMARY_GROUP_ID" AS "PRIMARYGROUPID",
   U1."LAST_MODIFIED_MEMBERSHIP" AS "LASTMODIFIEDMEMBERSHIP",
   U1."PASSWORD" AS "PASSWORD",
   U1."DISPLAY_NAME" AS "DISPLAYNAME",
   U1."EMAIL" AS "EMAIL",
   U1."ENABLED" AS "ENABLED",
   U1."LOCKED_UNTIL" AS "LOCKEDUNTIL",
   U1."LAST_LOGIN" AS "LASTLOGIN"
FROM
   "spotfire_server_1033"."dbo"."USERS" U1

2020-04-02T07:07:40,870+0530 [*pool-12-thread-4, boston\demo_user, #3, #6650*]: Information Link 'USERS' (01ea968e-2de6-458c-9bae-00f2b388db6e) executed successfully, time: 0.016 seconds
2020-04-02T07:07:40,932+0530 [*Thread-27, boston\demo_user, #3, #6650*]: Information Link 'USERS' (01ea968e-2de6-458c-9bae-00f2b388db6e) job closed, time: 0.078 seconds Doc: Changing server and node logging levels

• https://docs.tibco.com/pub/spotfire_server/10.3.9/doc/html/TIB_sfire_server_tsas_admin_help/GUID-397934BD-E610-4665-9B8F-A15B57658174.html

• https://docs.tibco.com/pub/spotfire_server/10.3.9/doc/html/TIB_sfire_server_tsas_admin_help/GUID-25179810-15E3-4032-8458-685C2531D9ED.html

• https://support.tibco.com/s/article/Troubleshooting-Guide-Performance-issues-with-Information-Links