firethorn

changeset 4202:a1390050bf66 2.1.28-tap-issues

Added more log samples
author Stelios <stv@roe.ac.uk>
date Thu Apr 18 19:40:52 2019 +0300 (2019-04-18)
parents ac3a19756ace
children ce08d680813f
files doc/notes/stv/20190418-Firethorn-Logs-Non-Propagating-2.txt doc/notes/stv/20190418-Firethorn-Logs-Propagating-2.txt
line diff
     1.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     1.2 +++ b/doc/notes/stv/20190418-Firethorn-Logs-Non-Propagating-2.txt	Thu Apr 18 19:40:52 2019 +0300
     1.3 @@ -0,0 +1,273 @@
     1.4 + 2019-04-18 16:26:44,255 DEBUG [FireThornTaskExecutor-4] [SQLServerOperator] SQL statement [CREATE TABLE [FirethornUserdataTAP20181212LIVE].[dbo].[XX_ARUX2DPOG7Y5WAAAAFVDCRMRNI] ([XX_SKFVOWAZYPD64AAAAFVDCRMSFM] VARBINARY(MAX) , [XX_YCRUDNPWICGY2AAAAFVDCRMSGQ] CHAR(10) , [XX_PHJSEYFU5TUPQAAAAFVDCRMSHE] CHAR(16) , [XX_UYWEQ3XZSHKJCAAAAFVDCRMSH4] CHAR(256) , [XX_46BXG6AC2432YAAAAFVDCRMSIQ] FLOAT , [XX_L2FTC64NBC4KSAAAAFVDCRMSJE] FLOAT , [XX_VGN3OBCSRUOEKAAAAFVDCRMSJY] FLOAT , [XX_3NOZLBSOUPDCYAAAAFVDCRMSKM] FLOAT , [XX_BL7PIDLEEEXNEAAAAFVDCRMSLA] FLOAT , [XX_T7YS4GJMDRRIEAAAAFVDCRMSLU] VARBINARY(MAX) )] 
     1.5 +2019-04-18 16:26:44,256 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
     1.6 +2019-04-18 16:26:44,256 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] open [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE][1] 
     1.7 +2019-04-18 16:26:44,257 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
     1.8 +2019-04-18 16:26:44,257 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
     1.9 +2019-04-18 16:26:44,257 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
    1.10 +2019-04-18 16:26:44,257 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] initialValue() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    1.11 +2019-04-18 16:26:44,258 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
    1.12 +2019-04-18 16:26:44,258 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] connect [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    1.13 +2019-04-18 16:26:44,258 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] State is CLOSED, updating to READY 
    1.14 +2019-04-18 16:26:44,258 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] State is READY, initialising Connection 
    1.15 +2019-04-18 16:26:44,259 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] With user/pass 
    1.16 +2019-04-18 16:26:44,259 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] connecting .... 
    1.17 +2019-04-18 16:26:44,265 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] .... connected 
    1.18 +2019-04-18 16:26:44,271 DEBUG [FireThornTaskExecutor-4] [SQLServerOperator] SQL result [0] 
    1.19 +2019-04-18 16:26:44,271 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
    1.20 +2019-04-18 16:26:44,271 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] close [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE][1] 
    1.21 +2019-04-18 16:26:44,271 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] operator() for [mssql] 
    1.22 +2019-04-18 16:26:44,271 DEBUG [FireThornTaskExecutor-4] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    1.23 +2019-04-18 16:26:44,272 INFO  [FireThornTaskExecutor-4] [AdqlQueryTimings] TIMING - jdbcdone() 
    1.24 +2019-04-18 16:26:44,276 DEBUG [FireThornTaskExecutor-4] [AdqlQueryTimings] AdqlQueryTimings() 
    1.25 +2019-04-18 16:26:44,294 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] before refresh() 
    1.26 +2019-04-18 16:26:44,306 DEBUG [FireThornTaskExecutor-3] [AdqlQueryTimings] AdqlQueryTimings() 
    1.27 +2019-04-18 16:26:44,307 DEBUG [FireThornTaskExecutor-3] [AdqlQueryTimings] AdqlQueryTimings() 
    1.28 +2019-04-18 16:26:44,308 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] after refresh() 
    1.29 +2019-04-18 16:26:44,308 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Getting base BaseResource 
    1.30 +2019-04-18 16:26:44,309 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Found base BaseResource [OSA JDBC] 
    1.31 +2019-04-18 16:26:44,309 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Getting direct resource 
    1.32 +2019-04-18 16:26:44,321 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] primary(JdbcResource) [2102] 
    1.33 +2019-04-18 16:26:44,331 DEBUG [FireThornTaskExecutor-3] [OgsaServiceEntity] primary() 
    1.34 +2019-04-18 16:26:44,339 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] primary(OgsaService, JdbcResource) [22702][2102] 
    1.35 +2019-04-18 16:26:44,346 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Found primary OgsaJdbcResource [69602] 
    1.36 +2019-04-18 16:26:44,346 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Checking ogsaid ... 
    1.37 +2019-04-18 16:26:44,346 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.38 +2019-04-18 16:26:44,346 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scan for [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.39 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scantest() 
    1.40 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.41 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69602] 
    1.42 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.43 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.730Z] 
    1.44 +2019-04-18 16:26:44,347 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] start time [2019-04-18T16:25:19.338Z] 
    1.45 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] prev scan is before startup - scanning 
    1.46 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Checking for existing lock [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.47 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] No existing lock found [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.48 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Adding new lock [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y][2019-04-18T16:26:44.348Z] 
    1.49 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Running scan [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.50 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scanimpl() 
    1.51 +2019-04-18 16:26:44,348 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.52 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69602] 
    1.53 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.54 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ping() 
    1.55 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.56 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69602] 
    1.57 +2019-04-18 16:26:44,349 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.58 +2019-04-18 16:26:44,361 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service request [69602][http://jarmila:8080/ogsadai/services/dataResources/ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.59 +2019-04-18 16:26:44,404 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service response [69602][null] 
    1.60 +2019-04-18 16:26:44,405 ERROR [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Ping test failed [69602][ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6][404] 
    1.61 +2019-04-18 16:26:44,406 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] status(status) 
    1.62 +2019-04-18 16:26:44,406 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.63 +2019-04-18 16:26:44,406 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69602] 
    1.64 +2019-04-18 16:26:44,406 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    1.65 +2019-04-18 16:26:44,406 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   status [ERROR] 
    1.66 +2019-04-18 16:26:44,412 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Releasing locks [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    1.67 +2019-04-18 16:26:44,412 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Found existing lock [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y][2019-04-18T16:26:44.348Z] 
    1.68 +2019-04-18 16:26:44,412 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Removing .... 
    1.69 +2019-04-18 16:26:44,412 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Notifying .... 
    1.70 +2019-04-18 16:26:44,413 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Found ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6][ERROR] 
    1.71 +2019-04-18 16:26:44,413 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Primary OgsaJdbcResource failed ping test, creating a new one 
    1.72 +2019-04-18 16:26:44,413 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] create(OgsaService, JdbcResource) [22702][2102] 
    1.73 +2019-04-18 16:26:44,415 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Using direct resource [XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
    1.74 +2019-04-18 16:26:44,415 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Getting source OgsaService 
    1.75 +2019-04-18 16:26:44,415 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Found source OgsaService [http://jarmila:8080/ogsadai/services] 
    1.76 +2019-04-18 16:26:44,415 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Getting target table 
    1.77 +2019-04-18 16:26:44,421 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
    1.78 +2019-04-18 16:26:44,421 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Found target table [[FirethornUserdataTAP20181212LIVE].[dbo].[XX_ARUX2DPOG7Y5WAAAAFVDCRMRNI]] 
    1.79 +2019-04-18 16:26:44,421 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Getting target OgsaBaseResource 
    1.80 +2019-04-18 16:26:44,421 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] primary(JdbcResource) [52] 
    1.81 +2019-04-18 16:26:44,422 DEBUG [FireThornTaskExecutor-3] [OgsaServiceEntity] primary() 
    1.82 +2019-04-18 16:26:44,424 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] primary(OgsaService, JdbcResource) [22702][52] 
    1.83 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Found primary OgsaJdbcResource [69603] 
    1.84 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Checking ogsaid ... 
    1.85 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
    1.86 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scan for [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    1.87 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scantest() 
    1.88 +2019-04-18 16:26:44,431 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    1.89 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69603] 
    1.90 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
    1.91 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.753Z] 
    1.92 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] start time [2019-04-18T16:25:19.338Z] 
    1.93 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] prev scan is before startup - scanning 
    1.94 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Checking for existing lock [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    1.95 +2019-04-18 16:26:44,432 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] No existing lock found [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    1.96 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Adding new lock [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54][2019-04-18T16:26:44.433Z] 
    1.97 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Running scan [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    1.98 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scanimpl() 
    1.99 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   1.100 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69603] 
   1.101 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   1.102 +2019-04-18 16:26:44,433 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ping() 
   1.103 +2019-04-18 16:26:44,434 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   1.104 +2019-04-18 16:26:44,434 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69603] 
   1.105 +2019-04-18 16:26:44,434 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   1.106 +2019-04-18 16:26:44,435 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service request [69603][http://jarmila:8080/ogsadai/services/dataResources/ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   1.107 +2019-04-18 16:26:44,444 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service response [69603][null] 
   1.108 +2019-04-18 16:26:44,444 ERROR [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Ping test failed [69603][ogsadai-0cec79d0-76da-4cba-b586-689d8d367817][404] 
   1.109 +2019-04-18 16:26:44,445 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] status(status) 
   1.110 +2019-04-18 16:26:44,445 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   1.111 +2019-04-18 16:26:44,445 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [69603] 
   1.112 +2019-04-18 16:26:44,445 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   1.113 +2019-04-18 16:26:44,446 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   status [ERROR] 
   1.114 +2019-04-18 16:26:44,446 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Releasing locks [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   1.115 +2019-04-18 16:26:44,446 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Found existing lock [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54][2019-04-18T16:26:44.433Z] 
   1.116 +2019-04-18 16:26:44,446 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Removing .... 
   1.117 +2019-04-18 16:26:44,446 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Notifying .... 
   1.118 +2019-04-18 16:26:44,447 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Found ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817][ERROR] 
   1.119 +2019-04-18 16:26:44,447 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] Primary OgsaJdbcResource failed ping test, creating a new one 
   1.120 +2019-04-18 16:26:44,447 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity$EntityFactory] create(OgsaService, JdbcResource) [22702][52] 
   1.121 +2019-04-18 16:26:44,448 DEBUG [FireThornTaskExecutor-3] [BlueQueryEntity] Found target OgsaBaseResource [XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.122 +2019-04-18 16:26:44,448 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] transition(TaskState) 
   1.123 +2019-04-18 16:26:44,448 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   ident [71452] 
   1.124 +2019-04-18 16:26:44,449 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   state [READY][RUNNING] 
   1.125 +2019-04-18 16:26:44,449 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] accept(TaskState) 
   1.126 +2019-04-18 16:26:44,449 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   ident [71452] 
   1.127 +2019-04-18 16:26:44,449 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   state [READY][RUNNING] 
   1.128 +2019-04-18 16:26:44,449 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] handle() [] 
   1.129 +2019-04-18 16:26:44,451 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity$Handle] event() [71452]:[RUNNING]->[RUNNING]:[false]->[true] 
   1.130 +2019-04-18 16:26:44,464 DEBUG [FireThornTaskExecutor-3] [OgsaExecResourceEntity$EntityFactory] primary(OgsaService) [22702] 
   1.131 +2019-04-18 16:26:44,469 DEBUG [FireThornTaskExecutor-3] [OgsaExecResourceEntity$EntityFactory] No primary OgsaExecResource, creating a new one 
   1.132 +2019-04-18 16:26:44,469 DEBUG [FireThornTaskExecutor-3] [OgsaExecResourceEntity$EntityFactory] simple(OgsaService) [22702] 
   1.133 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid [CREATED][DataRequestExecutionResource] 
   1.134 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scan for [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.135 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scantest() 
   1.136 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.137 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71654] 
   1.138 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   1.139 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] prevscan   [null] 
   1.140 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] start time [2019-04-18T16:25:19.338Z] 
   1.141 +2019-04-18 16:26:44,470 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scantest for [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.142 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [OgsaExecResourceEntity] factory() 
   1.143 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity$EntityFactory] scanperiod() 
   1.144 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity$EntityFactory]   value [PT11M] 
   1.145 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Factory scanperiod  [PT11M] 
   1.146 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] prevscan   [null] 
   1.147 +2019-04-18 16:26:44,471 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scanperiod [PT11M] 
   1.148 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] prev scan is null - scanning 
   1.149 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Checking for existing lock [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.150 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] No existing lock found [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.151 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Adding new lock [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU][2019-04-18T16:26:44.472Z] 
   1.152 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Running scan [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.153 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scanimpl() 
   1.154 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.155 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71654] 
   1.156 +2019-04-18 16:26:44,472 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   1.157 +2019-04-18 16:26:44,473 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ping() 
   1.158 +2019-04-18 16:26:44,473 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.159 +2019-04-18 16:26:44,473 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71654] 
   1.160 +2019-04-18 16:26:44,473 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   1.161 +2019-04-18 16:26:44,473 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service request [71654][http://jarmila:8080/ogsadai/services/dataResources/DataRequestExecutionResource] 
   1.162 +2019-04-18 16:26:44,543 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Service response [71654][null] 
   1.163 +2019-04-18 16:26:44,544 ERROR [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] Ping test failed [71654][DataRequestExecutionResource][404] 
   1.164 +2019-04-18 16:26:44,544 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] status(status) 
   1.165 +2019-04-18 16:26:44,544 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.166 +2019-04-18 16:26:44,544 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71654] 
   1.167 +2019-04-18 16:26:44,544 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   1.168 +2019-04-18 16:26:44,544 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   status [ERROR] 
   1.169 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Releasing locks [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU] 
   1.170 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Found existing lock [71654][XX_XCUY4JJS7FNKSAAAAFVDCRMTOU][2019-04-18T16:26:44.472Z] 
   1.171 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Removing .... 
   1.172 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Notifying .... 
   1.173 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid [CREATED][null] 
   1.174 +2019-04-18 16:26:44,545 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scan for [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.175 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scantest() 
   1.176 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.177 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71652] 
   1.178 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.179 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Checking for existing lock [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.180 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] No existing lock found [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.181 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Adding new lock [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU][2019-04-18T16:26:44.546Z] 
   1.182 +2019-04-18 16:26:44,546 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Running scan [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.183 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scanimpl() 
   1.184 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.185 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71652] 
   1.186 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.187 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] init() 
   1.188 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   name   [XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.189 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   ident  [71652] 
   1.190 +2019-04-18 16:26:44,547 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   ogsaid [null] 
   1.191 +2019-04-18 16:26:44,556 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Creating OGSA-DAI JDBC resource 
   1.192 +2019-04-18 16:26:44,556 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Executing JdbcCreateResourceWorkflow 
   1.193 +2019-04-18 16:26:44,569 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.194 +2019-04-18 16:26:44,569 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.195 +2019-04-18 16:26:44,572 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.196 +2019-04-18 16:26:44,572 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.197 +2019-04-18 16:26:45,785 DEBUG [FireThornTaskExecutor-3] [SimpleWorkflowResult] RequestExecutionStatus [uk.org.ogsadai.resource.request.status.COMPLETED] 
   1.198 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Status  [COMPLETED] 
   1.199 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Created [ogsadai-5bd2ced1-8a31-4c9c-88cd-ab82e352f8f2] 
   1.200 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid(status, ogsaid) 
   1.201 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.202 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71652] 
   1.203 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.204 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   status [ACTIVE] 
   1.205 +2019-04-18 16:26:45,786 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-5bd2ced1-8a31-4c9c-88cd-ab82e352f8f2] 
   1.206 +2019-04-18 16:26:45,787 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Releasing locks [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU] 
   1.207 +2019-04-18 16:26:45,787 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Found existing lock [71652][XX_AKTPZQZVBTO3MAAAAFVDCRMTHU][2019-04-18T16:26:44.546Z] 
   1.208 +2019-04-18 16:26:45,787 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Removing .... 
   1.209 +2019-04-18 16:26:45,787 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Notifying .... 
   1.210 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid [CREATED][null] 
   1.211 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] scan for [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.212 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scantest() 
   1.213 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.214 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71653] 
   1.215 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.216 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Checking for existing lock [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.217 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] No existing lock found [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.218 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Adding new lock [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4][2019-04-18T16:26:45.788Z] 
   1.219 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Running scan [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.220 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] scanimpl() 
   1.221 +2019-04-18 16:26:45,788 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.222 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71653] 
   1.223 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.224 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] init() 
   1.225 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   name   [XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.226 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   ident  [71653] 
   1.227 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity]   ogsaid [null] 
   1.228 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Creating OGSA-DAI JDBC resource 
   1.229 +2019-04-18 16:26:45,789 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Executing JdbcCreateResourceWorkflow 
   1.230 +2019-04-18 16:26:45,790 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.231 +2019-04-18 16:26:45,790 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.232 +2019-04-18 16:26:45,790 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.233 +2019-04-18 16:26:45,790 DEBUG [FireThornTaskExecutor-3] [JdbcConnectionEntity] operator() for [mssql] 
   1.234 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [SimpleWorkflowResult] RequestExecutionStatus [uk.org.ogsadai.resource.request.status.COMPLETED] 
   1.235 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Status  [COMPLETED] 
   1.236 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaJdbcResourceEntity] Created [ogsadai-f1f124f4-59ec-4843-956d-416a48923eb0] 
   1.237 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity] ogsaid(status, ogsaid) 
   1.238 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   name   [XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.239 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ident  [71653] 
   1.240 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [null] 
   1.241 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   status [ACTIVE] 
   1.242 +2019-04-18 16:26:46,019 DEBUG [FireThornTaskExecutor-3] [OgsaBaseResourceEntity]   ogsaid [ogsadai-f1f124f4-59ec-4843-956d-416a48923eb0] 
   1.243 +2019-04-18 16:26:46,020 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Releasing locks [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4] 
   1.244 +2019-04-18 16:26:46,020 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Found existing lock [71653][XX_YAKU2KDQJRYPUAAAAFVDCRMTL4][2019-04-18T16:26:45.788Z] 
   1.245 +2019-04-18 16:26:46,020 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Removing .... 
   1.246 +2019-04-18 16:26:46,020 DEBUG [FireThornTaskExecutor-3] [BaseComponentEntity] Notifying .... 
   1.247 +2019-04-18 16:26:46,103 DEBUG [FireThornTaskExecutor-3] [OgsaContextClient] monkey(MonkeyParam) 
   1.248 +2019-04-18 16:26:46,384 DEBUG [FireThornTaskExecutor-3] [SimpleWorkflowResult] RequestExecutionStatus [uk.org.ogsadai.resource.request.status.PROCESSING] 
   1.249 +2019-04-18 16:26:46,394 DEBUG [FireThornTaskExecutor-3] [AdqlQueryTimings] AdqlQueryTimings() 
   1.250 +2019-04-18 16:26:46,395 DEBUG [FireThornTaskExecutor-3] [AdqlQueryTimings] AdqlQueryTimings() 
   1.251 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] transition(TaskState) 
   1.252 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   ident [71452] 
   1.253 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   state [READY][RUNNING] 
   1.254 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] accept(TaskState) 
   1.255 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   ident [71452] 
   1.256 +2019-04-18 16:26:46,398 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   state [READY][RUNNING] 
   1.257 +2019-04-18 16:26:46,399 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity] After execute() 
   1.258 +2019-04-18 16:26:46,399 DEBUG [FireThornTaskExecutor-3] [BlueTaskEntity]   state [RUNNING] 
   1.259 +2019-04-18 16:26:46,405 DEBUG [FireThornTaskExecutor-3] [AdqlQueryTimings] AdqlQueryTimings() 
   1.260 +2019-04-18 16:26:46,412 DEBUG [FireThornTaskExecutor-2] [BlueTaskEntity] Finished thread() 
   1.261 +2019-04-18 16:26:46,412 DEBUG [FireThornTaskExecutor-2] [BlueTaskEntity]   state [READY] 
   1.262 +2019-04-18 16:26:46,412 DEBUG [FireThornTaskExecutor-2] [BlueTaskEntity] Refreshing state 
   1.263 +2019-04-18 16:26:46,417 DEBUG [FireThornTaskExecutor-2] [AdqlQueryTimings] AdqlQueryTimings() 
   1.264 +2019-04-18 16:26:46,418 DEBUG [FireThornTaskExecutor-2] [AdqlQueryTimings] AdqlQueryTimings() 
   1.265 +2019-04-18 16:26:46,419 DEBUG [FireThornTaskExecutor-2] [BlueTaskEntity] Finished running() 
   1.266 +2019-04-18 16:26:46,419 DEBUG [FireThornTaskExecutor-2] [BlueTaskEntity]   state [RUNNING] 
   1.267 +2019-04-18 16:26:46,420 DEBUG [main-interface-5] [BlueQueryEntity] Converting current instance [71452] 
   1.268 +2019-04-18 16:26:46,429 DEBUG [main-interface-5] [AdqlQueryTimings] AdqlQueryTimings() 
   1.269 +2019-04-18 16:26:46,429 DEBUG [main-interface-5] [AdqlQueryTimings] AdqlQueryTimings() 
   1.270 +2019-04-18 16:26:46,430 DEBUG [main-interface-5] [BlueTaskEntity] waitfor() [71452]:[RUNNING]->[RUNNING]->[COMPLETED]:[3000000] 
   1.271 +2019-04-18 16:26:46,430 DEBUG [main-interface-5] [BlueTaskEntity] handle() [] 
   1.272 +2019-04-18 16:26:46,436 DEBUG [main-interface-5] [BlueTaskEntity$BaseEventListener] waitfor(Handle) [71452][RUNNING] 
   1.273 +2019-04-18 16:26:46,437 DEBUG [main-interface-5] [BlueTaskEntity$StatusEventListener] test() [71452][RUNNING]->[RUNNING]->[COMPLETED] 
   1.274 +2019-04-18 16:26:46,437 DEBUG [main-interface-5] [BlueTaskEntity$BaseEventListener] test() [71452][1][3000000] 
   1.275 +
   1.276 +
     2.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     2.2 +++ b/doc/notes/stv/20190418-Firethorn-Logs-Propagating-2.txt	Thu Apr 18 19:40:52 2019 +0300
     2.3 @@ -0,0 +1,232 @@
     2.4 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [SQLServerOperator] SQL statement [CREATE TABLE [FirethornUserdataTAP20181212LIVE].[dbo].[XX_Z2WU66T7MYJ26AAAAFVDCQE6II] ([XX_QWGEDIRHFNKAWAAAAFVDCQE6QM] VARBINARY(MAX) , [XX_QCJSZDTUG3AV4AAAAFVDCQE6RI] CHAR(10) , [XX_QCCY3HXQSR27WAAAAFVDCQE6RY] CHAR(16) , [XX_CFOOUHSKDKWSQAAAAFVDCQE6SI] CHAR(256) , [XX_4ULR44DTLI2ESAAAAFVDCQE6SY] FLOAT , [XX_GO66ZBZ3YJFD2AAAAFVDCQE6TI] FLOAT , [XX_KG2H3G43DCIQOAAAAFVDCQE6T4] FLOAT , [XX_MTXMWGP3JP23CAAAAFVDCQE6UM] FLOAT , [XX_OOBCFXJ2WOZGYAAAAFVDCQE6VU] FLOAT , [XX_4E6TVG2OHHHPYAAAAFVDCQE6V4] VARBINARY(MAX) )] 
     2.5 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
     2.6 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] open [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE][1] 
     2.7 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
     2.8 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
     2.9 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
    2.10 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] initialValue() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    2.11 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
    2.12 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] connect [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    2.13 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] State is CLOSED, updating to READY 
    2.14 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] State is READY, initialising Connection 
    2.15 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] With user/pass 
    2.16 +2019-04-18 16:21:19,685 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] connecting .... 
    2.17 +2019-04-18 16:21:19,690 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] .... connected 
    2.18 +2019-04-18 16:21:19,695 DEBUG [FireThornTaskExecutor-50] [SQLServerOperator] SQL result [0] 
    2.19 +2019-04-18 16:21:19,695 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
    2.20 +2019-04-18 16:21:19,695 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] close [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE][1] 
    2.21 +2019-04-18 16:21:19,695 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] operator() for [mssql] 
    2.22 +2019-04-18 16:21:19,695 DEBUG [FireThornTaskExecutor-50] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/FirethornUserdataTAP20181212LIVE] 
    2.23 +2019-04-18 16:21:19,695 INFO  [FireThornTaskExecutor-50] [AdqlQueryTimings] TIMING - jdbcdone() 
    2.24 +2019-04-18 16:21:19,698 DEBUG [FireThornTaskExecutor-50] [AdqlQueryTimings] AdqlQueryTimings() 
    2.25 +2019-04-18 16:21:19,719 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] before refresh() 
    2.26 +2019-04-18 16:21:19,725 DEBUG [FireThornTaskExecutor-51] [AdqlQueryTimings] AdqlQueryTimings() 
    2.27 +2019-04-18 16:21:19,725 DEBUG [FireThornTaskExecutor-51] [AdqlQueryTimings] AdqlQueryTimings() 
    2.28 +2019-04-18 16:21:19,727 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] after refresh() 
    2.29 +2019-04-18 16:21:19,727 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Getting base BaseResource 
    2.30 +2019-04-18 16:21:19,727 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Found base BaseResource [OSA JDBC] 
    2.31 +2019-04-18 16:21:19,727 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Getting direct resource 
    2.32 +2019-04-18 16:21:19,728 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] primary(JdbcResource) [2102] 
    2.33 +2019-04-18 16:21:19,728 DEBUG [FireThornTaskExecutor-51] [OgsaServiceEntity] primary() 
    2.34 +2019-04-18 16:21:19,731 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] primary(OgsaService, JdbcResource) [22702][2102] 
    2.35 +2019-04-18 16:21:19,734 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Found primary OgsaJdbcResource [69602] 
    2.36 +2019-04-18 16:21:19,734 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Checking ogsaid ... 
    2.37 +2019-04-18 16:21:19,734 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    2.38 +2019-04-18 16:21:19,734 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scan for [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    2.39 +2019-04-18 16:21:19,735 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scantest() 
    2.40 +2019-04-18 16:21:19,735 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    2.41 +2019-04-18 16:21:19,735 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69602] 
    2.42 +2019-04-18 16:21:19,735 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
    2.43 +2019-04-18 16:21:19,735 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.730Z] 
    2.44 +2019-04-18 16:21:19,736 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] start time [2019-04-18T14:49:15.752Z] 
    2.45 +2019-04-18 16:21:19,736 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scantest for [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    2.46 +2019-04-18 16:21:19,737 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity] factory() 
    2.47 +2019-04-18 16:21:19,737 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory] scanperiod() 
    2.48 +2019-04-18 16:21:19,737 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory]   value [PT11M] 
    2.49 +2019-04-18 16:21:19,737 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Factory scanperiod  [PT11M] 
    2.50 +2019-04-18 16:21:19,738 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prevscan   [2019-04-18T16:20:47.730Z] 
    2.51 +2019-04-18 16:21:19,738 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scanperiod [PT11M] 
    2.52 +2019-04-18 16:21:19,738 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prev scan is recent - skipping 
    2.53 +2019-04-18 16:21:19,738 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Found ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6][ACTIVE] 
    2.54 +2019-04-18 16:21:19,738 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Using direct resource [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
    2.55 +2019-04-18 16:21:19,739 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Getting source OgsaService 
    2.56 +2019-04-18 16:21:19,739 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Found source OgsaService [http://jarmila:8080/ogsadai/services] 
    2.57 +2019-04-18 16:21:19,739 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Getting target table 
    2.58 +2019-04-18 16:21:19,743 DEBUG [FireThornTaskExecutor-51] [JdbcConnectionEntity] operator() for [mssql] 
    2.59 +2019-04-18 16:21:19,743 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Found target table [[FirethornUserdataTAP20181212LIVE].[dbo].[XX_Z2WU66T7MYJ26AAAAFVDCQE6II]] 
    2.60 +2019-04-18 16:21:19,743 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Getting target OgsaBaseResource 
    2.61 +2019-04-18 16:21:19,744 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] primary(JdbcResource) [52] 
    2.62 +2019-04-18 16:21:19,744 DEBUG [FireThornTaskExecutor-51] [OgsaServiceEntity] primary() 
    2.63 +2019-04-18 16:21:19,745 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] primary(OgsaService, JdbcResource) [22702][52] 
    2.64 +2019-04-18 16:21:19,747 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Found primary OgsaJdbcResource [69603] 
    2.65 +2019-04-18 16:21:19,748 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Checking ogsaid ... 
    2.66 +2019-04-18 16:21:19,748 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
    2.67 +2019-04-18 16:21:19,748 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scan for [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    2.68 +2019-04-18 16:21:19,748 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scantest() 
    2.69 +2019-04-18 16:21:19,749 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    2.70 +2019-04-18 16:21:19,749 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69603] 
    2.71 +2019-04-18 16:21:19,749 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
    2.72 +2019-04-18 16:21:19,749 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.753Z] 
    2.73 +2019-04-18 16:21:19,750 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] start time [2019-04-18T14:49:15.752Z] 
    2.74 +2019-04-18 16:21:19,750 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scantest for [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    2.75 +2019-04-18 16:21:19,750 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity] factory() 
    2.76 +2019-04-18 16:21:19,751 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory] scanperiod() 
    2.77 +2019-04-18 16:21:19,751 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory]   value [PT11M] 
    2.78 +2019-04-18 16:21:19,751 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Factory scanperiod  [PT11M] 
    2.79 +2019-04-18 16:21:19,751 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prevscan   [2019-04-18T16:20:47.753Z] 
    2.80 +2019-04-18 16:21:19,752 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scanperiod [PT11M] 
    2.81 +2019-04-18 16:21:19,752 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prev scan is recent - skipping 
    2.82 +2019-04-18 16:21:19,752 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity$EntityFactory] Found ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817][ACTIVE] 
    2.83 +2019-04-18 16:21:19,752 DEBUG [FireThornTaskExecutor-51] [BlueQueryEntity] Found target OgsaBaseResource [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
    2.84 +2019-04-18 16:21:19,752 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] transition(TaskState) 
    2.85 +2019-04-18 16:21:19,753 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   ident [69439] 
    2.86 +2019-04-18 16:21:19,753 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   state [READY][RUNNING] 
    2.87 +2019-04-18 16:21:19,753 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] accept(TaskState) 
    2.88 +2019-04-18 16:21:19,753 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   ident [69439] 
    2.89 +2019-04-18 16:21:19,753 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   state [READY][RUNNING] 
    2.90 +2019-04-18 16:21:19,754 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] handle() [] 
    2.91 +2019-04-18 16:21:19,754 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity$Handle] event() [69439]:[RUNNING]->[RUNNING]:[false]->[true] 
    2.92 +2019-04-18 16:21:19,755 DEBUG [FireThornTaskExecutor-51] [OgsaExecResourceEntity$EntityFactory] primary(OgsaService) [22702] 
    2.93 +2019-04-18 16:21:19,757 DEBUG [FireThornTaskExecutor-51] [OgsaExecResourceEntity$EntityFactory] No primary OgsaExecResource, creating a new one 
    2.94 +2019-04-18 16:21:19,757 DEBUG [FireThornTaskExecutor-51] [OgsaExecResourceEntity$EntityFactory] simple(OgsaService) [22702] 
    2.95 +2019-04-18 16:21:19,757 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ogsaid [CREATED][DataRequestExecutionResource] 
    2.96 +2019-04-18 16:21:19,757 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scan for [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
    2.97 +2019-04-18 16:21:19,758 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scantest() 
    2.98 +2019-04-18 16:21:19,758 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
    2.99 +2019-04-18 16:21:19,758 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69641] 
   2.100 +2019-04-18 16:21:19,758 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   2.101 +2019-04-18 16:21:19,758 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] prevscan   [null] 
   2.102 +2019-04-18 16:21:19,759 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] start time [2019-04-18T14:49:15.752Z] 
   2.103 +2019-04-18 16:21:19,759 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scantest for [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.104 +2019-04-18 16:21:19,759 DEBUG [FireThornTaskExecutor-51] [OgsaExecResourceEntity] factory() 
   2.105 +2019-04-18 16:21:19,759 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory] scanperiod() 
   2.106 +2019-04-18 16:21:19,760 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory]   value [PT11M] 
   2.107 +2019-04-18 16:21:19,760 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Factory scanperiod  [PT11M] 
   2.108 +2019-04-18 16:21:19,760 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prevscan   [null] 
   2.109 +2019-04-18 16:21:19,760 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scanperiod [PT11M] 
   2.110 +2019-04-18 16:21:19,760 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prev scan is null - scanning 
   2.111 +2019-04-18 16:21:19,761 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Checking for existing lock [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.112 +2019-04-18 16:21:19,761 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] No existing lock found [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.113 +2019-04-18 16:21:19,761 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Adding new lock [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU][2019-04-18T16:21:19.761Z] 
   2.114 +2019-04-18 16:21:19,761 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Running scan [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.115 +2019-04-18 16:21:19,761 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scanimpl() 
   2.116 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.117 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69641] 
   2.118 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   2.119 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ping() 
   2.120 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.121 +2019-04-18 16:21:19,762 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69641] 
   2.122 +2019-04-18 16:21:19,763 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   2.123 +2019-04-18 16:21:19,763 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] Service request [69641][http://jarmila:8080/ogsadai/services/dataResources/DataRequestExecutionResource] 
   2.124 +2019-04-18 16:21:19,769 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] Service response [69641][null] 
   2.125 +2019-04-18 16:21:19,769 ERROR [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] Ping test failed [69641][DataRequestExecutionResource][404] 
   2.126 +2019-04-18 16:21:19,770 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] status(status) 
   2.127 +2019-04-18 16:21:19,770 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.128 +2019-04-18 16:21:19,770 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69641] 
   2.129 +2019-04-18 16:21:19,771 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [DataRequestExecutionResource] 
   2.130 +2019-04-18 16:21:19,771 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   status [ERROR] 
   2.131 +2019-04-18 16:21:19,772 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Releasing locks [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU] 
   2.132 +2019-04-18 16:21:19,772 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Found existing lock [69641][XX_PHUYNISZALBVEAAAAFVDCQE7BU][2019-04-18T16:21:19.761Z] 
   2.133 +2019-04-18 16:21:19,772 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Removing .... 
   2.134 +2019-04-18 16:21:19,772 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Notifying .... 
   2.135 +2019-04-18 16:21:19,773 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
   2.136 +2019-04-18 16:21:19,773 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scan for [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
   2.137 +2019-04-18 16:21:19,773 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scantest() 
   2.138 +2019-04-18 16:21:19,773 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
   2.139 +2019-04-18 16:21:19,774 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69602] 
   2.140 +2019-04-18 16:21:19,774 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b0a4219c-7ef8-40ea-9c3d-2f482313d0a6] 
   2.141 +2019-04-18 16:21:19,774 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.730Z] 
   2.142 +2019-04-18 16:21:19,775 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] start time [2019-04-18T14:49:15.752Z] 
   2.143 +2019-04-18 16:21:19,775 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scantest for [69602][XX_QHRA4VEJ6UAUKAAAAFVDB3OF2Y] 
   2.144 +2019-04-18 16:21:19,775 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity] factory() 
   2.145 +2019-04-18 16:21:19,775 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory] scanperiod() 
   2.146 +2019-04-18 16:21:19,775 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory]   value [PT11M] 
   2.147 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Factory scanperiod  [PT11M] 
   2.148 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prevscan   [2019-04-18T16:20:47.730Z] 
   2.149 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scanperiod [PT11M] 
   2.150 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prev scan is recent - skipping 
   2.151 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   2.152 +2019-04-18 16:21:19,776 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scan for [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   2.153 +2019-04-18 16:21:19,777 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] scantest() 
   2.154 +2019-04-18 16:21:19,777 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   name   [XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   2.155 +2019-04-18 16:21:19,777 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ident  [69603] 
   2.156 +2019-04-18 16:21:19,777 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity]   ogsaid [ogsadai-0cec79d0-76da-4cba-b586-689d8d367817] 
   2.157 +2019-04-18 16:21:19,777 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] prevscan   [2019-04-18T16:20:47.753Z] 
   2.158 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [OgsaBaseResourceEntity] start time [2019-04-18T14:49:15.752Z] 
   2.159 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scantest for [69603][XX_UDKY4JFC63UWMAAAAFVDB3OF54] 
   2.160 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [OgsaJdbcResourceEntity] factory() 
   2.161 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory] scanperiod() 
   2.162 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity$EntityFactory]   value [PT11M] 
   2.163 +2019-04-18 16:21:19,778 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] Factory scanperiod  [PT11M] 
   2.164 +2019-04-18 16:21:19,779 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prevscan   [2019-04-18T16:20:47.753Z] 
   2.165 +2019-04-18 16:21:19,779 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] scanperiod [PT11M] 
   2.166 +2019-04-18 16:21:19,779 DEBUG [FireThornTaskExecutor-51] [BaseComponentEntity] prev scan is recent - skipping 
   2.167 +2019-04-18 16:21:19,876 DEBUG [FireThornTaskExecutor-51] [OgsaContextClient] monkey(MonkeyParam) 
   2.168 +2019-04-18 16:21:19,997 DEBUG [FireThornTaskExecutor-51] [SimpleWorkflowResult] RequestExecutionStatus [uk.org.ogsadai.resource.request.status.COMPLETED_WITH_ERROR] 
   2.169 +2019-04-18 16:21:20,005 DEBUG [FireThornTaskExecutor-51] [AdqlQueryTimings] AdqlQueryTimings() 
   2.170 +2019-04-18 16:21:20,005 DEBUG [FireThornTaskExecutor-51] [AdqlQueryTimings] AdqlQueryTimings() 
   2.171 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] transition(TaskState) 
   2.172 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   ident [69439] 
   2.173 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   state [READY][FAILED] 
   2.174 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] accept(TaskState) 
   2.175 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   ident [69439] 
   2.176 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   state [READY][FAILED] 
   2.177 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity] After execute() 
   2.178 +2019-04-18 16:21:20,007 DEBUG [FireThornTaskExecutor-51] [BlueTaskEntity]   state [FAILED] 
   2.179 +2019-04-18 16:21:20,010 DEBUG [FireThornTaskExecutor-51] [AdqlQueryTimings] AdqlQueryTimings() 
   2.180 +2019-04-18 16:21:20,016 DEBUG [FireThornTaskExecutor-52] [BlueTaskEntity] Finished thread() 
   2.181 +2019-04-18 16:21:20,016 DEBUG [FireThornTaskExecutor-52] [BlueTaskEntity]   state [READY] 
   2.182 +2019-04-18 16:21:20,016 DEBUG [FireThornTaskExecutor-52] [BlueTaskEntity] Refreshing state 
   2.183 +2019-04-18 16:21:20,020 DEBUG [FireThornTaskExecutor-52] [AdqlQueryTimings] AdqlQueryTimings() 
   2.184 +2019-04-18 16:21:20,020 DEBUG [FireThornTaskExecutor-52] [AdqlQueryTimings] AdqlQueryTimings() 
   2.185 +2019-04-18 16:21:20,021 DEBUG [FireThornTaskExecutor-52] [BlueTaskEntity] Finished running() 
   2.186 +2019-04-18 16:21:20,021 DEBUG [FireThornTaskExecutor-52] [BlueTaskEntity]   state [FAILED] 
   2.187 +2019-04-18 16:21:20,025 DEBUG [main-interface-2] [BlueQueryEntity] Converting current instance [69439] 
   2.188 +2019-04-18 16:21:20,032 DEBUG [main-interface-2] [AdqlQueryTimings] AdqlQueryTimings() 
   2.189 +2019-04-18 16:21:20,032 DEBUG [main-interface-2] [AdqlQueryTimings] AdqlQueryTimings() 
   2.190 +2019-04-18 16:21:20,033 DEBUG [main-interface-2] [BlueTaskEntity] waitfor() [69439]:[FAILED]->[FAILED]->[COMPLETED]:[3000000] 
   2.191 +2019-04-18 16:21:20,033 DEBUG [main-interface-2] [BlueTaskEntity] handle() [] 
   2.192 +2019-04-18 16:21:20,034 DEBUG [main-interface-2] [BlueQueryEntity] update(Handle) [69439][FAILED][RUNNING] 
   2.193 +2019-04-18 16:21:20,034 DEBUG [main-interface-2] [BlueQueryEntity] transition() [69439][EMPTY][EMPTY][0] 
   2.194 +2019-04-18 16:21:20,034 DEBUG [main-interface-2] [BlueQueryEntity] No-op state change [EMPTY][EMPTY] 
   2.195 +2019-04-18 16:21:20,054 DEBUG [main-interface-2] [AbstractEntityController] Operation [71091] 
   2.196 +2019-04-18 16:21:20,054 DEBUG [main-interface-2] [AbstractEntityController] Authentication [Authentication[Ident[71141]Identity[784632fc-23f1-4588-9732-6b6938e6697c]Method[urn:simple.http.header]]] 
   2.197 +2019-04-18 16:21:20,055 DEBUG [main-interface-2] [AbstractEntityController] Identity  [69208][784632fc-23f1-4588-9732-6b6938e6697c] 
   2.198 +2019-04-18 16:21:20,055 DEBUG [main-interface-2] [AbstractEntityController] Community [102][friends] 
   2.199 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug] Response headers 
   2.200 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [X-Clacks-Overhead][GNU Terry Pratchett] 
   2.201 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [Location][http://localhost:...] 
   2.202 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [firethorn.auth.username][784632fc-23f1-458...] 
   2.203 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [firethorn.auth.community][friends] 
   2.204 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [Content-Type][application/json;...] 
   2.205 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [Transfer-Encoding][chunked] 
   2.206 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [Date][Thu, 18 Apr 2019 ...] 
   2.207 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug]   [Connection][close] 
   2.208 +2019-04-18 16:21:20,065 DEBUG [main-interface-2] [HttpRequestDebug] ---- 
   2.209 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug] Request properties 
   2.210 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug]   requestURL  [http://localhost:8081/firethorn/system/info] 
   2.211 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug]   queryString [null] 
   2.212 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug]   authType    [null] 
   2.213 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug]   remoteAddr  [127.0.0.1] 
   2.214 +2019-04-18 16:21:20,119 DEBUG [callback-interface-2] [HttpRequestDebug] Request headers 
   2.215 +2019-04-18 16:21:20,120 DEBUG [callback-interface-2] [HttpRequestDebug]   [host][localhost:8081] 
   2.216 +2019-04-18 16:21:20,120 DEBUG [callback-interface-2] [HttpRequestDebug]   [user-agent][curl/7.59.0] 
   2.217 +2019-04-18 16:21:20,120 DEBUG [callback-interface-2] [HttpRequestDebug]   [accept][*/*] 
   2.218 +2019-04-18 16:21:20,120 DEBUG [callback-interface-2] [HttpRequestDebug] Request parameters 
   2.219 +2019-04-18 16:21:20,120 DEBUG [callback-interface-2] [HttpRequestDebug] ---- 
   2.220 +2019-04-18 16:21:20,124 DEBUG [callback-interface-2] [AnonymousAuthenticator] Adding anonymous Authentication 
   2.221 +2019-04-18 16:21:20,126 DEBUG [callback-interface-2] [IdentityEntity] create(Community) [friends] 
   2.222 +2019-04-18 16:21:20,148 DEBUG [callback-interface-2] [OperationEntity] authenticate() [71092][71038][anon-6G7MPQVEDIQHUAAAAFVDCQFAPY][urn:anonymous] 
   2.223 +2019-04-18 16:21:20,148 DEBUG [callback-interface-2] [AuthMethodEntity] create() [71092][71038][anon-6G7MPQVEDIQHUAAAAFVDCQFAPY][urn:anonymous] 
   2.224 +2019-04-18 16:21:20,152 DEBUG [callback-interface-2] [OperationEntity] primary(Authentication) 
   2.225 +2019-04-18 16:21:20,152 DEBUG [callback-interface-2] [OperationEntity]   Authentication [Authentication[Ident[71142]Identity[anon-6G7MPQVEDIQHUAAAAFVDCQFAPY]Method[urn:anonymous]]] 
   2.226 +2019-04-18 16:21:20,152 DEBUG [callback-interface-2] [OperationEntity]   Identity [entity[class[uk.ac.roe.wfau.firethorn.identity.IdentityEntity] ident[71038]]] 
   2.227 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug] Response headers 
   2.228 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug]   [X-Clacks-Overhead][GNU Terry Pratchett] 
   2.229 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug]   [firethorn.auth.identity][http://localhost:...] 
   2.230 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug]   [firethorn.auth.username][anon-6G7MPQVEDIQH...] 
   2.231 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug]   [firethorn.auth.community][friends] 
   2.232 +2019-04-18 16:21:20,153 DEBUG [callback-interface-2] [HttpRequestDebug] ---- 
   2.233 +
   2.234 +
   2.235 +