firethorn

changeset 4311:aebbf8399c31 2.1.35-stv-issue-1182

Adding notes on Debugging TAP issue
author Stelios <stv@roe.ac.uk>
date Wed Sep 09 18:44:08 2020 +0300 (15 months ago)
parents 7049be534b83
children 310132961970
files doc/notes/stv/20200909-Debugging-TAP.txt
line diff
     1.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     1.2 +++ b/doc/notes/stv/20200909-Debugging-TAP.txt	Wed Sep 09 18:44:08 2020 +0300
     1.3 @@ -0,0 +1,895 @@
     1.4 +
     1.5 +#
     1.6 +# <meta:header>
     1.7 +#   <meta:licence>
     1.8 +#     Copyright (c) 2020, ROE (http://www.roe.ac.uk/)
     1.9 +#
    1.10 +#     This information is free software: you can redistribute it and/or modify
    1.11 +#     it under the terms of the GNU General Public License as published by
    1.12 +#     the Free Software Foundation, either version 3 of the License, or
    1.13 +#     (at your option) any later version.
    1.14 +#
    1.15 +#     This information is distributed in the hope that it will be useful,
    1.16 +#     but WITHOUT ANY WARRANTY; without even the implied warranty of
    1.17 +#     MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
    1.18 +#     GNU General Public License for more details.
    1.19 +#
    1.20 +#     You should have received a copy of the GNU General Public License
    1.21 +#     along with this program.  If not, see <http://www.gnu.org/licenses/>.
    1.22 +#   </meta:licence>
    1.23 +# </meta:header>
    1.24 +#
    1.25 +#
    1.26 +
    1.27 +
    1.28 +
    1.29 +
    1.30 +
    1.31 +# Query: Select top 1 * from VHSDR6.vhsSource
    1.32 +
    1.33 +
    1.34 +# Try with CURL
    1.35 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+*+from+VHSDR6.vhsSource&LANG=ADQL"
    1.36 + 
    1.37 +  > .... <TD>7.3028411865234375</TD><TD>1</TD><TD>23.328332901000977</TD><TD>1</TD><TD>2.5094616413116455</TD><TD>4194496</TD><TD>1</TD><TD>-0.06073231250047684</TD><TD>0.22702492773532867</TD></TR></TABLEDATA></DATA></TABLE></RESOURCE></VOTABLE>
    1.38 +
    1.39 +  # Success
    1.40 +
    1.41 +
    1.42 +# Try with TOPCAT
    1.43 +
    1.44 +  # Success
    1.45 +
    1.46 +
    1.47 +# ---------------------------------------------
    1.48 +
    1.49 +# Query: Select top 1000 * from VHSDR6.vhsSource
    1.50 +
    1.51 +# Try with CURL
    1.52 +
    1.53 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1000+*+from+VHSDR6.vhsSource&LANG=ADQL"
    1.54 +..
    1.55 +<TD>26.910812377929688</TD><TD>0</TD><TD>99.51732635498047</TD><TD>1</TD><TD>0.25515878200531006</TD><TD>0</TD><TD>728</TD><TD>0.06916654109954834</TD><TD>-0.1225629523396492</TD></TR></TABLEDATA></DATA></TABLE></RESOURCE></VOTABLE>
    1.56 +
    1.57 +  # Success
    1.58 +
    1.59 +
    1.60 +# Try with TOPCAT
    1.61 +
    1.62 +  # Success
    1.63 +
    1.64 +
    1.65 +# ---------------------------------------------
    1.66 +
    1.67 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+10000+*+from+VHSDR6.vhsSource&LANG=ADQL"
    1.68 +
    1.69 +...
    1.70 +<TD>0.006278033368289471</TD><TD>15.26
    1.71 +* transfer closed with outstanding read data remaining
    1.72 +* stopped the pause stream!
    1.73 +* Closing connection 0
    1.74 +curl: (18) transfer closed with outstanding read data remaining
    1.75 +
    1.76 +# Seems to return a truncated VOTable..
    1.77 +
    1.78 +# Checking logs:
    1.79 +
    1.80 +  # Apache logs:
    1.81 +  	[Wed Sep 09 10:49:58.303000 2020] [proxy_http:error] [pid 926:tid 140533098985216] (20014)Internal error (specific information not available): [client 195.194.121.66:39078] AH01110: error reading response
    1.82 +
    1.83 +  # Ogsadai logs:
    1.84 +	2020-09-09 10:49:48,039 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:157] callback(String, Long)
    1.85 +	2020-09-09 10:49:48,039 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:158]   task    [COMPLETED]
    1.86 +	2020-09-09 10:49:48,040 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:159]   results [COMPLETED]
    1.87 +	2020-09-09 10:49:48,040 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:160]   count   [10000]
    1.88 +	2020-09-09 10:49:48,040 DEBUG context.RequestContextFactory [pool-1-thread-100,endpoint:130] endpoint [http://gillian:8081/firethorn]
    1.89 +	2020-09-09 10:49:48,040 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:178] Before callback
    1.90 +	2020-09-09 10:49:48,040 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:179]   Ident    [4797034]
    1.91 +	2020-09-09 10:49:48,041 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:180]   Endpoint [http://gillian:8081/firethorn/blue/query/callback/4797034]
    1.92 +	2020-09-09 10:49:48,137 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:215] Response bean
    1.93 +	2020-09-09 10:49:48,137 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:216]   Ident [4797034]
    1.94 +	2020-09-09 10:49:48,138 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:217]   Name  [XX_CTSPD6O3TJQHMAAAAF2HE7CMZY]
    1.95 +	2020-09-09 10:49:48,138 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:218]   State [COMPLETED]
    1.96 +	2020-09-09 10:49:48,139 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4797034]
    1.97 +	2020-09-09 10:49:48,139 DEBUG blue.CallbackHandler [pool-1-thread-100,callback:226] After callback
    1.98 +	2020-09-09 10:49:48,140 DEBUG activity.MatchedIterativeActivity [pool-1-thread-100,debug:84] performing last stage of processing
    1.99 +	2020-09-09 10:49:48,140 DEBUG activity.MatchedIterativeActivity [pool-1-thread-100,debug:84] performing clean-up
   1.100 +	2020-09-09 10:49:48,141 DEBUG event.LoggingActivityListener [pool-1-thread-100,debug:84] COMPLETED: Activity uk.ac.roe.wfau.firethorn.JdbcInsertData (instance name = uk.ac.roe.wfau.firethorn.JdbcInsertData-ogsadai-cb5d7eea-574a-4111-87ea-51335ddb60c8)
   1.101 +	2020-09-09 10:49:48,141 DEBUG event.LoggingActivityListener [pool-1-thread-101,debug:84] COMPLETED: Activity uk.org.ogsadai.DeliverToRequestStatus (instance name = uk.org.ogsadai.DeliverToRequestStatus-ogsadai-a10c1158-2d56-46eb-b307-b7cfe1d791b9)
   1.102 +
   1.103 +
   1.104 +  # FT logs:
   1.105 +   
   1.106 +   .. Nothing obvious, no exceptions
   1.107 +	  2020-09-09 10:57:12,720 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838690] 
   1.108 +	2020-09-09 10:57:12,720 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_A3EM5JPMDT2EWAAAAF2HFAYX7E] 
   1.109 +	2020-09-09 10:57:12,720 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.110 +	2020-09-09 10:57:12,720 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.111 +	2020-09-09 10:57:12,720 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838692] 
   1.112 +	2020-09-09 10:57:12,720 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_NUSL7IL4WC3ZWAAAAF2HFAYX7M] 
   1.113 +	2020-09-09 10:57:12,721 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.114 +	2020-09-09 10:57:12,721 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.115 +	2020-09-09 10:57:12,721 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838694] 
   1.116 +	2020-09-09 10:57:12,721 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_Q6CGVJI643GSMAAAAF2HFAYX7U] 
   1.117 +	2020-09-09 10:57:12,721 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.118 +	2020-09-09 10:57:12,722 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.119 +	2020-09-09 10:57:12,722 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838696] 
   1.120 +	2020-09-09 10:57:12,722 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListeneramses2/LIVEFirethornUserdataULOV20190307
   1.121 +r]  name  [XX_VT3W2VVTXXMQKAAAAF2HFAYX7Y] 
   1.122 +	2020-09-09 10:57:12,722 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.123 +	2020-09-09 10:57:12,723 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.124 +	2020-09-09 10:57:12,723 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838698] 
   1.125 +	2020-09-09 10:57:12,723 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_7LG5FBZQKARPMAAAAF2HFAYYAA] 
   1.126 +	2020-09-09 10:57:12,723 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.127 +	2020-09-09 10:57:12,724 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.128 +	2020-09-09 10:57:12,724 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838700] 
   1.129 +	2020-09-09 10:57:12,724 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_3HF5I37ECZSUWAAAAF2HFAYYAE] 
   1.130 +	2020-09-09 10:57:12,724 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.131 +	2020-09-09 10:57:12,725 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.132 +	2020-09-09 10:57:12,725 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838702] 
   1.133 +	2020-09-09 10:57:12,725 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_BNQP6PHMCQLSIAAAAF2HFAYYAM] 
   1.134 +	2020-09-09 10:57:12,725 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.135 +	2020-09-09 10:57:12,726 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.136 +	2020-09-09 10:57:12,726 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838704] 
   1.137 +	2020-09-09 10:57:12,726 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_JLIHPTZVIGS6AAAAAF2HFAYYAU] 
   1.138 +	2020-09-09 10:57:12,726 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.139 +	2020-09-09 10:57:12,726 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.140 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838706] 
   1.141 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_HDIGVPG43RI5AAAAAF2HFAYYAY] 
   1.142 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.143 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.144 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838708] 
   1.145 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_DQBOPG6TRKRC2AAAAF2HFAYYBA] 
   1.146 +	2020-09-09 10:57:12,727 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.147 +	2020-09-09 10:57:12,728 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.148 +	2020-09-09 10:57:12,728 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838710] 
   1.149 +	2020-09-09 10:57:12,728 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_ZYFKY7UTX6SEYAAAAF2HFAYYBI] 
   1.150 +	2020-09-09 10:57:12,728 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.151 +	2020-09-09 10:57:12,729 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.152 +	2020-09-09 10:57:12,729 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838712] 
   1.153 +	2020-09-09 10:57:12,729 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_RARKLQI3WZVA6AAAAF2HFAYYBM] 
   1.154 +	2020-09-09 10:57:12,729 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.155 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.156 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838714] 
   1.157 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_YNDSMAEDAJ5Z4AAAAF2HFAYYBU] 
   1.158 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.159 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.160 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838716] 
   1.161 +	2020-09-09 10:57:12,730 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_4NWBU3F2JEYFOAAAAF2HFAYYBY] 
   1.162 +	2020-09-09 10:57:12,731 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.163 +	2020-09-09 10:57:12,731 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.164 +	2020-09-09 10:57:12,731 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  ident [4838718] 
   1.165 +	2020-09-09 10:57:12,731 DEBUG [main-interface-6] [JdbcColumnEntity$EntityListener]  name  [XX_JMV36QWEQMRQEAAAAF2HFAYYCA] 
   1.166 +	2020-09-09 10:57:12,731 DEBUG [main-interface-6] [AdqlColumnEntity] services() 
   1.167 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.168 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] open [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307][1] 
   1.169 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.170 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.171 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.172 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] initialValue() [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.173 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.174 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] connect [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.175 +	2020-09-09 10:57:12,733 DEBUG [main-interface-6] [JdbcConnectionEntity] Source is null, updating to EMPTY 
   1.176 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] State is EMPTY, initialising DataSource 
   1.177 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.178 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.179 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] State is READY, initialising Connection 
   1.180 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] With user/pass 
   1.181 +	2020-09-09 10:57:12,734 DEBUG [main-interface-6] [JdbcConnectionEntity] connecting .... 
   1.182 +	2020-09-09 10:57:12,738 DEBUG [main-interface-6] [JdbcConnectionEntity] .... connected 
   1.183 +	2020-09-09 10:57:12,738 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.184 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [JdbcConnectionEntity] operator() for [mssql] 
   1.185 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [AdqlTableEntity] columns() for [4797445][temp.XX_LFK6AXALUMWMAAAAAF2HFAYXBE] 
   1.186 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [BaseComponentEntity] scan for [4797445][XX_LFK6AXALUMWMAAAAAF2HFAYXBE] 
   1.187 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [BaseComponentEntity] scantest for [4797445][XX_LFK6AXALUMWMAAAAAF2HFAYXBE] 
   1.188 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [BaseComponentEntity$EntityFactory] scanperiod() 
   1.189 +	2020-09-09 10:57:12,739 DEBUG [main-interface-6] [BaseComponentEntity$EntityFactory]   value [PT25H] 
   1.190 +	2020-09-09 10:57:12,740 DEBUG [main-interface-6] [BaseComponentEntity] Factory scanperiod  [PT25H] 
   1.191 +	2020-09-09 10:57:12,740 DE# Let's test the same query in TopcatBUG [main-interface-6] [BaseComponentEntity] prevscan   [2020-09-09T10:57:07.905Z] 
   1.192 +	2020-09-09 10:57:12,740 DEBUG [main-interface-6] [BaseComponentEntity] scanperiod [PT25H] 
   1.193 +	2020-09-09 10:57:12,740 DEBUG [main-interface-6] [BaseComponentEntity] prev scan is recent - skipping 
   1.194 +	2020-09-09 10:57:12,754 DEBUG [main-interface-6] [AbstractTableController] VOTABLE SQL [SELECT [XX_D5R7LSSJDZ67EAAAAF2HFAYXIA] AS sourceID, [XX_XDYPRTASPNO7UAAAAF2HFAYXII] AS cuEventID, [XX_QJACWNV4NT73QAAAAF2HFAYXIQ] AS frameSetID, [XX_DOBUTGLPQD426AAAAF2HFAYXIY] AS ra, [XX_QFURFRAQH6IUCAAAAF2HFAYXJA] AS dec, [XX_HGHEHDF6FECRYAAAAF2HFAYXJI] AS cx, [XX_SUOAVUHZDCFPIAAAAF2HFAYXJM] AS cy, [XX_W4FTTOA75T2HEAAAAF2HFAYXJU] AS cz, [XX_2UZ3IPJU4IXWWAAAAF2HFAYXJ4] AS htmID, [XX_67B6L3KTAYKVKAAAAF2HFAYXKA] AS l, [XX_GI2D53TH4Y67MAAAAF2HFAYXKI] AS b, [XX_D6DP2QPMHPEV2AAAAF2HFAYXKM] AS lambda, [XX_AHSMMTIJGVKRMAAAAF2HFAYXKU] AS eta, [XX_W6VNJE6VJ2IJQAAAAF2HFAYXK4] AS priOrSec, [XX_HYD33RWOVASQEAAAAF2HFAYXLA] AS ymjPnt, [XX_N6IBKAIYZHSAMAAAAF2HFAYXLI] AS ymjPntErr, [XX_KQCG2TJD4RZCKAAAAF2HFAYXLM] AS jmhPnt, [XX_WILIA24TI3QBYAAAAF2HFAYXLU] AS jmhPntErr, [XX_VSJX3VD3B7TZ2AAAAF2HFAYXLY] AS hmksPnt, [XX_KY24L7CZNG7UEAAAAF2HFAYXMA] AS hmksPntErr, [XX_ELAJLVNRDK434AAAAF2HFAYXMI] AS jmksPnt, [XX_QUWGNHEBEQSFKAAAAF2HFAYXMM] AS jmksPntErr, [XX_PHJQLUCSZQMI2AAAAF2HFAYXMU] AS ymjExt, [XX_BT3KS7EEAY2SMAAAAF2HFAYXMY] AS ymjExtErr, [XX_QHXYJQSK7JZEMAAAAF2HFAYXNA] AS jmhExt, [XX_XH72BD47VCCPQAAAAF2HFAYXNE] AS jmhExtErr, [XX_AOCPZMTFTGC5OAAAAF2HFAYXNI] AS hmksExt, [XX_747D2DLQPDHQMAAAAF2HFAYXNQ] AS hmksExtErr, [XX_XHLGOKI6RBCWEAAAAF2HFAYXNU] AS jmksExt, [XX_FAYHH3UCOOAPWAAAAF2HFAYXN4] AS jmksExtErr, [XX_TUZ3TNDGJCEL6AAAAF2HFAYXOA] AS mergedClassStat, [XX_RRTHE5N2SQKXOAAAAF2HFAYXOE] AS mergedClass, [XX_PWZ6EZDCBKH7OAAAAF2HFAYXOM] AS pStar, [XX_YCH6FI2LAY7JCAAAAF2HFAYXOQ] AS pGalaxy, [XX_O6A5ITVPWZK4UAAAAF2HFAYXOU] AS pNoise, [XX_RU6T7P23MHQFAAAAAF2HFAYXO4] AS pSaturated, [XX_DIHKIDLB3SZCUAAAAF2HFAYXPA] AS eBV, [XX_Q7DTVU5NPPNTCAAAAF2HFAYXPE] AS aY, [XX_GO5LIOV2XJGL4AAAAF2HFAYXPM] AS aJ, [XX_QYHC6MSOSWTKIAAAAF2HFAYXPQ] AS aH, [XX_CPD7D6VIWZPWAAAAAF2HFAYXPU] AS aKs, [XX_ZIB2N26T6W5Y6AAAAF2HFAYXPY] AS yMjd, [XX_XSTSC4RKA5EKAAAAAF2HFAYXQA] AS yPetroMag, [XX_VYX66WFZGLHMSAAAAF2HFAYXQE] AS yPetroMagErr, [XX_6DZDUSIIM3XD4AAAAF2HFAYXQI] AS yPsfMag, [XX_2CS33EZVXPN2AAAAAF2HFAYXQQ] AS yPsfMagErr, [XX_HWS5ILGRADX3GAAAAF2HFAYXQU] AS ySerMag2D, [XX_GYK6F62GM37FIAAAAF2HFAYXQY] AS ySerMag2DErr, [XX_ERV2GT4IASUKSAAAAF2HFAYXQ4] AS yAperMag3, [XX_UL2RDMVXCEPJSAAAAF2HFAYXRE] AS yAperMag3Err, [XX_KEEAJZK2QUBX4AAAAF2HFAYXRI] AS yAperMag4, [XX_OTS3CINPTBVBSAAAAF2HFAYXRM] AS yAperMag4Err, [XX_KU6JXJ34SAN4MAAAAF2HFAYXRQ] AS yAperMag6, [XX_TLL4E45GXOPPAAAAAF2HFAYXRU] AS yAperMag6Err, [XX_X2Y7YU3UVCYMMAAAAF2HFAYXRY] AS yAperMagNoAperCorr3, [XX_42INKF5EVATC4AAAAF2HFAYXSA] AS yAperMagNoAperCorr4, [XX_PK5GUKKRBNT7UAAAAF2HFAYXSE] AS yAperMagNoAperCorr6, [XX_22HAWQDOID7FSAAAAF2HFAYXSI] AS yHlCorSMjRadAs, [XX_MP72G3VGNHPY6AAAAF2HFAYXSM] AS yGausig, [XX_ENZC4Y4JNB26QAAAAF2HFAYXSQ] AS yEll, [XX_QZW333ODAWIOSAAAAF2HFAYXSU] AS yPA, [XX_2BY5HPYJ2224SAAAAF2HFAYXSY] AS yErrBits, [XX_DXWRG4ZUKSBR6AAAAF2HFAYXS4] AS yAverageConf, [XX_HJXZBT55I4N5YAAAAF2HFAYXTA] AS yClass, [XX_SS6T4TUYTHGXUAAAAF2HFAYXTI] AS yClassStat, [XX_UW5D7WU5AZSXKAAAAF2HFAYXTM] AS yppErrBits, [XX_Z2BSLV5ZDPU7UAAAAF2HFAYXTQ] AS ySeqNum, [XX_C2PVIZTCFOU54AAAAF2HFAYXTU] AS yXi, [XX_3VOBVZQU4LL5CAAAAF2HFAYXTY] AS yEta, [XX_2VBT7O5ZAYSNEAAAAF2HFAYXT4] AS jMjd, [XX_22EAIVSXFAG6KAAAAF2HFAYXUA] AS jPetroMag, [XX_3FY6K3GXRHIQIAAAAF2HFAYXUE] AS jPetroMagErr, [XX_3R6JXCVP4I6VEAAAAF2HFAYXUI] AS jPsfMag, [XX_P5MR7TBJYTJJMAAAAF2HFAYXUQ] AS jPsfMagErr, [XX_TRZ3RZ5IC3R6MAAAAF2HFAYXUU] AS jSerMag2D, [XX_KJPVI4C6U6Y2EAAAAF2HFAYXUY] AS jSerMag2DErr, [XX_NXDLAVWW3OXKIAAAAF2HFAYXU4] AS jAperMag3, [XX_N6EBRM26VJSLKAAAAF2HFAYXVA] AS jAperMag3Err, [XX_7GUL3RGPGGWEEAAAAF2HFAYXVE] AS jAperMag4, [XX_7UMOMNM5DAVU4AAAAF2HFAYXVI] AS jAperMag4Err, [XX_2IJIDIV2ERH2UAAAAF2HFAYXVM] AS jAperMag6, [XX_PFX56WWEBQ4GIAAAAF2HFAYXVQ] AS jAperMag6Err, [XX_U3YI2Z2T2ZBH2AAAAF2HFAYXVU] AS jAperMagNoAperCorr3, [XX_F47KHSPSNEWN2AAAAF2HFAYXVY] AS jAperMagNoAperCorr4, [XX_3DTQACLNMYDYWAAAAF2HFAYXV4] AS jAperMagNoAperCorr6, [XX_6GNTJ3FCKVRBQAAAAF2HFAYXWA] AS jHlCorSMjRadAs, [XX_AE6DFBNI2RWVYAAAAF2HFAYXWE] AS jGausig, [XX_L2MOU4WWAYCGIAAAAF2HFAYXWI] AS jEll, [XX_U26HIYG7K3IKUAAAAF2HFAYXWM] AS jPA, [XX_JNNXNUKX4L6YMAAAAF2HFAYXWQ] AS jErrBits, [XX_X6UNQHEFX4XOKAAAAF2HFAYXWU] AS jAverageConf, [XX_VDK7XO5SJWXTQAAAAF2HFAYXWY] AS jClass, [XX_2EBQ7RDN4QEK4AAAAF2HFAYXW4] AS jClassStat, [XX_ESUC5MACSR62IAAAAF2HFAYXXA] AS jppErrBits, [XX_OPEFSY3XGIKFYAAAAF2HFAYXXE] AS jSeqNum, [XX_AXFY227R3UU62AAAAF2HFAYXXI] AS jXi, [XX_ZDWXXCY32HAHUAAAAF2HFAYXXM] AS jEta, [XX_JEBKE47OB76KMAAAAF2HFAYXXQ] AS hMjd, [XX_5UW5DUSLBKDEMAAAAF2HFAYXXU] AS hPetroMag, [XX_ZU6FTDRUBXAFQAAAAF2HFAYXXY] AS hPetroMagErr, [XX_ZX7WST5MZYGDIAAAAF2HFAYXX4] AS hPsfMag, [XX_OROWIRK3XKGACAAAAF2HFAYXYA] AS hPsfMagErr, [XX_3E7C2IZ5SUMGUAAAAF2HFAYXYE] AS hSerMag2D, [XX_PEQ242G5U5OZAAAAAF2HFAYXYI] AS hSerMag2DErr, [XX_4FQCF2ZM7BJUCAAAAF2HFAYXYM] AS hAperMag3, [XX_34D6FDLZMSCGUAAAAF2HFAYXYQ] AS hAperMag3Err, [XX_HBCLOTQMV3M4UAAAAF2HFAYXYU] AS hAperMag4, [XX_ZV4P5CD2Y3N6QAAAAF2HFAYXYY] AS hAperMag4Err, [XX_OLYRU5FI3SQEMAAAAF2HFAYXY4] AS hAperMag6, [XX_3OO7P5E3VHK5OAAAAF2HFAYXY4] AS hAperMag6Err, [XX_QDF2ZDKV3KSK2AAAAF2HFAYXZA] AS hAperMagNoAperCorr3, [XX_Z2KXBMVG7BKPMAAAAF2HFAYXZE] AS hAperMagNoAperCorr4, [XX_YEUHUSA24LYSSAAAAF2HFAYXZI] AS hAperMagNoAperCorr6, [XX_B75XWZIRAZLXWAAAAF2HFAYXZM] AS hHlCorSMjRadAs, [XX_RI4MSWHEJJXJQAAAAF2HFAYXZY] AS hGausig, [XX_F32W74TQQVYY6AAAAF2HFAYX2A] AS hEll, [XX_ESX3J6WTGKDQ2AAAAF2HFAYX2I] AS hPA, [XX_CIZ5ABRCTYL42AAAAF2HFAYX2Q] AS hErrBits, [XX_S6W5U2WT3SME4AAAAF2HFAYX2Y] AS hAverageConf, [XX_DWODXEDL6644OAAAAF2HFAYX3A] AS hClass, [XX_YDDBK2O7BE3FQAAAAF2HFAYX3I] AS hClassStat, [XX_OKGXKQQXXGWICAAAAF2HFAYX3Q] AS hppErrBits, [XX_DQWUZO5OBU65OAAAAF2HFAYX3Y] AS hSeqNum, [XX_TXXXOE7MZ3SPIAAAAF2HFAYX4A] AS hXi, [XX_KFTU5KZUQ23K6AAAAF2HFAYX4I] AS hEta, [XX_POAZNQSQ62BIYAAAAF2HFAYX4M] AS ksMjd, [XX_CEBL3A7F3ODHMAAAAF2HFAYX4U] AS ksPetroMag, [XX_2IMLUSIYNMU2WAAAAF2HFAYX44] AS ksPetroMagErr, [XX_CA3AYF5H5PZPOAAAAF2HFAYX5E] AS ksPsfMag, [XX_GC7ZY3OQFMXCIAAAAF2HFAYX5I] AS ksPsfMagErr, [XX_65XYUPKXUL2LAAAAAF2HFAYX5Q] AS ksSerMag2D, [XX_4DVSCNWIFOG4AAAAAF2HFAYX5Y] AS ksSerMag2DErr, [XX_5EVICSXPJZMVIAAAAF2HFAYX54] AS ksAperMag3, [XX_KY2LU3WB765LYAAAAF2HFAYX6E] AS ksAperMag3Err, [XX_32NWBH5R5C3EWAAAAF2HFAYX6M] AS ksAperMag4, [XX_MBGNYJTPYA3ESAAAAF2HFAYX6Q] AS ksAperMag4Err, [XX_PACPUHBZX4VS2AAAAF2HFAYX6Y] AS ksAperMag6, [XX_RALYCLW6HH5QWAAAAF2HFAYX7A] AS ksAperMag6Err, [XX_A3EM5JPMDT2EWAAAAF2HFAYX7E] AS ksAperMagNoAperCorr3, [XX_NUSL7IL4WC3ZWAAAAF2HFAYX7M] AS ksAperMagNoAperCorr4, [XX_Q6CGVJI643GSMAAAAF2HFAYX7U] AS ksAperMagNoAperCorr6, [XX_VT3W2VVTXXMQKAAAAF2HFAYX7Y] AS ksHlCorSMjRadAs, [XX_7LG5FBZQKARPMAAAAF2HFAYYAA] AS ksGausig, [XX_3HF5I37ECZSUWAAAAF2HFAYYAE] AS ksEll, [XX_BNQP6PHMCQLSIAAAAF2HFAYYAM] AS ksPA, [XX_JLIHPTZVIGS6AAAAAF2HFAYYAU] AS ksErrBits, [XX_HDIGVPG43RI5AAAAAF2HFAYYAY] AS ksAverageConf, [XX_DQBOPG6TRKRC2AAAAF2HFAYYBA] AS ksClass, [XX_ZYFKY7UTX6SEYAAAAF2HFAYYBI] AS ksClassStat, [XX_RARKLQI3WZVA6AAAAF2HFAYYBM] AS ksppErrBits, [XX_YNDSMAEDAJ5Z4AAAAF2HFAYYBU] AS ksSeqNum, [XX_4NWBU3F2JEYFOAAAAF2HFAYYBY] AS ksXi, [XX_JMV36QWEQMRQEAAAAF2HFAYYCA] AS ksEta FROM [LIVEFirethornUserdataULOV20190307].[dbo].[XX_LFK6AXALUMWMAAAAAF2HFAYXBE]] 
   1.195 +
   1.196 +
   1.197 +# Try with TOPCAT
   1.198 +
   1.199 +
   1.200 +java.io.IOException: TAP response is not a VOTable - <?xml version='1.0' encoding='UTF-8'?><VOTABLE xmlns='http://www.ivoa.net/xml/VOTable/v1.3' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance' xsi:schemaLocation='http://www.ivoa.net/xml/VOTable/v1.3 http://www.ivoa.net/xml/VOTable/v1.3' version='1.3'><RESOURCE type='results'><INFO name='QUERY_STATUS' value='OK'></INFO><INFO name='link' value='http://tap.roe.ac.uk/firethorn/adql/table/4841161'/><TABLE ID='table.4841161' name='XX_FGSDFKQBDH526AAAAF2HFQSSZ4'><FIELD ID='column.4845559' name='sourceID' datatype='long'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845559'/></FIELD><FIELD ID='column.4845561' name='cuEventID' datatype='int'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845561'/></FIELD><FIELD ID='column.4845563' name='frameSetID' datatype='long'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845563'/></FIELD><FIELD ID='column.4845565' name='ra' datatype='double'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845565'/></FIELD><FIELD ID='column.4845567' name='dec' datatype='double'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845567'/></FIELD><FIELD ID='column.4845569' name='cx' datatype='double'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845569'/></FIELD><FIELD ID='column.4845571' name='cy' datatype='double'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845571'/></FIELD><FIELD ID='column.4845573' name='cz' datatype='double'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4845573'/></FIELD><FIELD ID='column.4845575' name='htmID' datatype='long'><LINK content-type='application/json' con ...
   1.201 +	at uk.ac.starlink.vo.TapQuery.readResultVOTable(TapQuery.java:637)
   1.202 +	at uk.ac.starlink.vo.TapQuery.executeSync(TapQuery.java:244)
   1.203 +	at uk.ac.starlink.vo.TapTableLoadDialog$6.loadTables(TapTableLoadDialog.java:538)
   1.204 +	at uk.ac.starlink.table.gui.TableLoadWorker.run(TableLoadWorker.java:118)
   1.205 +Caused by: org.xml.sax.SAXParseException; systemId: http://tap.roe.ac.uk/vsa/sync; lineNumber: 1; columnNumber: 531783; The element type "TD" must be terminated by the matching end-tag "</TD>".
   1.206 +	at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.createSAXParseException(ErrorHandlerWrapper.java:203)
   1.207 +	at com.sun.org.apache.xerces.internal.util.ErrorHandlerWrapper.fatalError(ErrorHandlerWrapper.java:177)
   1.208 +	at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:400)
   1.209 +	at com.sun.org.apache.xerces.internal.impl.XMLErrorReporter.reportError(XMLErrorReporter.java:327)
   1.210 +	at com.sun.org.apache.xerces.internal.impl.XMLScanner.reportFatalError(XMLScanner.java:1473)
   1.211 +	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanEndElement(XMLDocumentFragmentScannerImpl.java:1749)
   1.212 +	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(XMLDocumentFragmentScannerImpl.java:2967)
   1.213 +	at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(XMLDocumentScannerImpl.java:602)
   1.214 +	at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(XMLDocumentFragmentScannerImpl.java:505)
   1.215 +	at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:842)
   1.216 +	at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(XML11Configuration.java:771)
   1.217 +	at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(XMLParser.java:141)
   1.218 +	at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(AbstractSAXParser.java:1213)
   1.219 +	at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(SAXParserImpl.java:643)
   1.220 +	at uk.ac.starlink.votable.VOElementFactory.parseToDOM(VOElementFactory.java:536)
   1.221 +	at uk.ac.starlink.votable.VOElementFactory.transformToDOM(VOElementFactory.java:391)
   1.222 +	at uk.ac.starlink.votable.VOElementFactory.makeVOElement(VOElementFactory.java:221)
   1.223 +	at uk.ac.starlink.votable.VOElementFactory.makeVOElement(VOElementFactory.java:241)
   1.224 +	at uk.ac.starlink.vo.TapQuery.readResultVOTable(TapQuery.java:622)
   1.225 +	... 3 more
   1.226 +
   1.227 +
   1.228 +# Check the query results for the failed Topcat query:
   1.229 +
   1.230 +curl http://tap.roe.ac.uk/firethorn/blue/query/4797046
   1.231 +
   1.232 +   >	.. 
   1.233 +	"input": "select top 10000 * from VHSDR6.vhsSource",
   1.234 +	"status": "COMPLETED",
   1.235 +	"results": {
   1.236 +	"formats": {
   1.237 +	"datatable": "http://tap.roe.ac.uk/firethorn/adql/table/4841161/datatable",
   1.238 +	"votable": "http://tap.roe.ac.uk/firethorn/adql/table/4841161/votable"
   1.239 +	},
   1.240 +	"count": 10000,
   1.241 +	"state": "COMPLETED",
   1.242 +	"table": "http://tap.roe.ac.uk/firethorn/adql/table/4841161"
   1.243 +	},
   1.244 +
   1.245 +# Query History shows a series of RUNNING, then a COMPLETED status
   1.246 +
   1.247 +
   1.248 +# Check table results in User database
   1.249 +
   1.250 +SELECT 
   1.251 +  COUNT(*)
   1.252 +  FROM [LIVEFirethornUserdataULOV20190307].[dbo].[XX_FGSDFKQBDH526AAAAF2HFQSSZ4]
   1.253 +
   1.254 +# 10000
   1.255 +
   1.256 +
   1.257 +
   1.258 +
   1.259 +# ---------------------------------------------
   1.260 +
   1.261 +
   1.262 +
   1.263 +# Query: Select top 100000 * from VHSDR6.vhsSource
   1.264 +
   1.265 +
   1.266 +# Try with CURL
   1.267 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+100000+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.268 + 
   1.269 +
   1.270 +	> ...
   1.271 +
   1.272 +	<TD>-39.39365211355716</TD><T* transfer closed with outstanding read data remaining
   1.273 +	* stopped the pause stream!
   1.274 +	* Closing connection 0
   1.275 +	curl: (18) transfer closed with outstanding read data remaining
   1.276 +	D>-0.6068918682117606</TD><TD>0.4784434292944761</TD><TD>-0.6346448969804931</TD><TD>10978704616990</TD><TD>265.5078937947085</TD><TD>8.188101610321466</TD><TD>-31.972820809886624</TD><TD>-80.92933
   1.277 +
   1.278 +# Failed, same as above example
   1.279 +	
   1.280 +
   1.281 +
   1.282 +# Try again
   1.283 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+100000+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.284 +
   1.285 +	> ...
   1.286 +	</TD><* Connection #0 to host tap.roe.ac.uk left intact
   1.287 +	TD>1.4068139791488647</TD><TD>0.24551093578338623</TD><TD>7.3028411865234375</TD><TD>1</TD><TD>23.328332901000977</TD><TD>1</TD><TD>2.5094616413116455</TD><TD>4194496</TD><TD>1</TD><TD>-0.06073231250047684</TD><TD>0.22702492773532867</TD></TR></TABLEDATA></DATA></TABLE></RESOURCE></VOTABLE>
   1.288 +
   1.289 +
   1.290 +# Success
   1.291 +
   1.292 +
   1.293 +# Try a third time
   1.294 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+100000+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.295 +
   1.296 +	> ...
   1.297 +	<TD>-9.99999488E8</TD><TD>-9.99999488E8<
   1.298 +	* transfer closed with outstanding read data remaining
   1.299 +	* stopped the pause stream!
   1.300 +	* Closing connection 0
   1.301 +	curl: (18) transfer closed with outstanding read data remaining
   1.302 +
   1.303 +
   1.304 +# Failed, truncated VOTable again
   1.305 +# Same exception in Apache:
   1.306 + 
   1.307 + [Wed Sep 09 12:27:50.016880 2020] [proxy_http:error] [pid 927:tid 140532974073600] (20014)Internal error (specific information not available): [client 195.194.121.66:41516] AH01110: error reading response
   1.308 +
   1.309 +
   1.310 +# ---------------------------------------------
   1.311 +
   1.312 +
   1.313 +
   1.314 +# Query: Select top 1000000 * from VHSDR6.vhsSource
   1.315 +
   1.316 +
   1.317 +# Try with CURL
   1.318 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1000000+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.319 +
   1.320 +*   Trying 129.215.175.100...
   1.321 +* TCP_NODELAY set
   1.322 +* Connected to tap.roe.ac.uk (129.215.175.100) port 80 (#0)
   1.323 +> GET /vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1000000+*+from+VHSDR6.vhsSource&LANG=ADQL HTTP/1.1
   1.324 +> Host: tap.roe.ac.uk
   1.325 +> User-Agent: curl/7.58.0
   1.326 +> Accept: */*
   1.327 +> 
   1.328 +
   1.329 +# Hangs..
   1.330 +
   1.331 +
   1.332 +# Last OGSADAI Logs:
   1.333 +
   1.334 +2020-09-09 12:31:13,576 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:217]   Name  [XX_37Z3QZKEUAQ7IAAAAF2HFWIZPY]
   1.335 +2020-09-09 12:31:13,577 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:218]   State [RUNNING]
   1.336 +2020-09-09 12:31:13,577 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4797050]
   1.337 +2020-09-09 12:31:13,577 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:226] After callback
   1.338 +2020-09-09 12:31:19,627 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:157] callback(String, Long)
   1.339 +2020-09-09 12:31:19,627 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:158]   task    [RUNNING]
   1.340 +2020-09-09 12:31:19,627 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:159]   results [PARTIAL]
   1.341 +2020-09-09 12:31:19,628 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:160]   count   [65535]
   1.342 +2020-09-09 12:31:19,628 DEBUG context.RequestContextFactory [pool-1-thread-173,endpoint:130] endpoint [http://gillian:8081/firethorn]
   1.343 +2020-09-09 12:31:19,629 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:178] Before callback
   1.344 +2020-09-09 12:31:19,629 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:179]   Ident    [4797050]
   1.345 +2020-09-09 12:31:19,629 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:180]   Endpoint [http://gillian:8081/firethorn/blue/query/callback/4797050]
   1.346 +2020-09-09 12:31:19,730 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:215] Response bean
   1.347 +2020-09-09 12:31:19,730 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:216]   Ident [4797050]
   1.348 +2020-09-09 12:31:19,731 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:217]   Name  [XX_37Z3QZKEUAQ7IAAAAF2HFWIZPY]
   1.349 +2020-09-09 12:31:19,732 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:218]   State [RUNNING]
   1.350 +2020-09-09 12:31:19,732 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4797050]
   1.351 +2020-09-09 12:31:19,733 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:226] After callback
   1.352 +
   1.353 +
   1.354 +
   1.355 +# Last FT logs
   1.356 + ..
   1.357 +
   1.358 +  # Very verbose, output mostly system info checks, not sure which part to post here.. 
   1.359 + 2OBEY] BIGINT , [XX_QP345KQ7Z6LKCAAAAF2HF2OBFA] INTEGER , [XX_46PZMHS5BF6GWAAAAF2HF2OBFE] BIGINT , [XX_5YM4SEA72PIHMAAAAF2HF2OBFI] FLOAT , [XX_MNHMQI67LH64WAAAAF2HF2OBFQ] FLOAT , [XX_OFQ2G7RNFRRI4AAAAF2HF2OBFU] FLOAT , [XX_2NDKVBQFGWPHIAAAAF2HF2OBF4] FLOAT , [XX_4HGLH3UNCHKHEAAAAF2HF2OBGA] FLOAT , [XX_D6SGD5BBFPJ3MAAAAF2HF2OBGI] BIGINT , [XX_R7QONZD3Z5N5UAAAAF2HF2OBGQ] FLOAT , [XX_MARA3YHZT3YFOAAAAF2HF2OBGU] FLOAT , [XX_NRHYXYZCZ3XTOAAAAF2HF2OBGY] FLOAT , [XX_JHE52A2IN3PQ4AAAAF2HF2OBHA] FLOAT , [XX_ZN2TD5P4EUUCUAAAAF2HF2OBHE] BIGINT , [XX_ANDTDVNOKCWQSAAAAF2HF2OBHI] FLOAT , [XX_MFEJIJ6FY33AWAAAAF2HF2OBHQ] FLOAT , [XX_V6D5OGPUTTSGQAAAAF2HF2OBHU] FLOAT , [XX_Z2FJMC4B2MQGGAAAAF2HF2OBHY] FLOAT , [XX_QKPUIUKHT23L6AAAAF2HF2OBIA] FLOAT , [XX_UBEVANMETGMXEAAAAF2HF2OBIE] FLOAT , [XX_AEO7EQMKVX3ZQAAAAF2HF2OBII] FLOAT , [XX_6MECZPZ4JKQKUAAAAF2HF2OBIM] FLOAT , [XX_DZHL66IGTXTO6AAAAF2HF2OBIQ] FLOAT , [XX_AMPRHRJRO62TCAAAAF2HF2OBIU] FLOAT , [XX_JIGGJRD2JLF3IAAAAF2HF2OBIY] FLOAT , [XX_2QRKPZ522BMGGAAAAF2HF2OBIY] FLOAT , [XX_EMQPTNYEKBPEYAAAAF2HF2OBI4] FLOAT , [XX_YFTZFTYBYSQE4AAAAF2HF2OBJA] FLOAT , [XX_N5QYSKLUGMBRCAAAAF2HF2OBJE] FLOAT , [XX_HHZODIKA66NDKAAAAF2HF2OBJI] FLOAT , [XX_F333LNKQQXKM2AAAAF2HF2OBJM] FLOAT , [XX_EJUXDDEYVN6Q4AAAAF2HF2OBJQ] SMALLINT , [XX_DSFW4OSG257UGAAAAF2HF2OBJQ] FLOAT , [XX_K7IGYQTQSGWAIAAAAF2HF2OBJY] FLOAT , [XX_WA7LEW6JN7U2MAAAAF2HF2OBJ4] FLOAT , [XX_SYYNI5ZBVCEPKAAAAF2HF2OBJ4] FLOAT , [XX_Y6WWOACWFCYSAAAAAF2HF2OBKA] FLOAT , [XX_SZYCEY4OCELPIAAAAF2HF2OBKE] FLOAT , [XX_NFRTVVCA5JZU2AAAAF2HF2OBKI] FLOAT , [XX_R3X7AR3AAZWMQAAAAF2HF2OBKM] FLOAT , [XX_WZ4ZVRHDTDUL2AAAAF2HF2OBKQ] FLOAT , [XX_MLDLNYHEMD3WYAAAAF2HF2OBKU] FLOAT , [XX_AFH3NBOEO7HXKAAAAF2HF2OBKY] FLOAT , [XX_WORZT5OYJ6GI2AAAAF2HF2OBKY] FLOAT , [XX_FSHJKD43KKSW4AAAAF2HF2OBK4] FLOAT , [XX_XKXUJUINGBGQ6AAAAF2HF2OBLA] FLOAT , [XX_5HVTSHA46EZRKAAAAF2HF2OBLE] FLOAT , [XX_IT55NPLYWNLYSAAAAF2HF2OBLI] FLOAT , [XX_FRMNLKY3ULS4UAAAAF2HF2OBLM] FLOAT , [XX_OBK57DJCWFFMIAAAAF2HF2OBLM] FLOAT , [XX_EWORE7W25L5GCAAAAF2HF2OBLQ] FLOAT , [XX_ZWEGYFLFL6MD6AAAAF2HF2OBLU] FLOAT , [XX_ON4GBH3LS532IAAAAF2HF2OBLY] FLOAT , [XX_LVTCFLQ7ZSTK4AAAAF2HF2OBL4] FLOAT , [XX_WTKF5VUEZT4M4AAAAF2HF2OBMA] FLOAT , [XX_OYUW7NONZXCHOAAAAF2HF2OBME] FLOAT , [XX_TOVE4NEV2FEBCAAAAF2HF2OBME] FLOAT , [XX_7364EDPTZDVDGAAAAF2HF2OBMI] FLOAT , [XX_WSJZNDF3T3EREAAAAF2HF2OBMM] FLOAT , [XX_S7B5PGPQARGTGAAAAF2HF2OBMQ] FLOAT , [XX_RE3FV5O4RKZWQAAAAF2HF2OBMU] FLOAT , [XX_GNRRTRIOMXA7SAAAAF2HF2OBMY] INTEGER , [XX_O4AB4S3LRAOSAAAAAF2HF2OBM4] FLOAT , [XX_MM5AT6NOZPXLUAAAAF2HF2OBNA] SMALLINT , [XX_R7QHPLB32HKTYAAAAF2HF2OBNE] FLOAT , [XX_CJ734LDJNNG6GAAAAF2HF2OBNE] INTEGER , [XX_D325N6S5AUHC6AAAAF2HF2OBNI] INTEGER , [XX_XCUG2T273EAJCAAAAF2HF2OBNM] FLOAT , [XX_65PFSXRO63MGEAAAAF2HF2OBNQ] FLOAT , [XX_DIPQXXCUVVYROAAAAF2HF2OBNU] FLOAT , [XX_Q6PK3QN3ZZWLGAAAAF2HF2OBNY] FLOAT , [XX_Q3S7QUFW5DCXYAAAAF2HF2OBN4] FLOAT , [XX_ZBIQSVPOFZDPCAAAAF2HF2OBN4] FLOAT , [XX_E3YLPLUJQMQ7UAAAAF2HF2OBOE] FLOAT , [XX_QEHCYDLIOYIGCAAAAF2HF2OBOI] FLOAT , [XX_JREMD6PS2K5YCAAAAF2HF2OBOM] FLOAT , [XX_BLBHKHEZM5NDYAAAAF2HF2OBOQ] FLOAT , [XX_6NHV5PKKWG5DCAAAAF2HF2OBOY] FLOAT , [XX_VLQQPAZJW4UC4AAAAF2HF2OBO4] FLOAT , [XX_SGXJDAVRRXV6GAAAAF2HF2OBPE] FLOAT , [XX_34TP47IFKZFNSAAAAF2HF2OBPI] FLOAT , [XX_CTFRMXUVZRDKCAAAAF2HF2OBPM] FLOAT , [XX_OXQLEDQSPKFFAAAAAF2HF2OBPU] FLOAT , [XX_PDEW4ZIQFI5SUAAAAF2HF2OBPY] FLOAT , [XX_DLRQW7I7WKQJYAAAAF2HF2OBP4] FLOAT , [XX_WF37YLNLA3LW6AAAAF2HF2OBQE] FLOAT , [XX_CWVOTVNRR4CDWAAAAF2HF2OBQI] FLOAT , [XX_W2YDAV73XW4RSAAAAF2HF2OBQQ] FLOAT , [XX_KFKJMZY7VGBJYAAAAF2HF2OBQU] FLOAT , [XX_MYAMMBDQPXIAAAAAAF2HF2OBQY] INTEGER , [XX_NNOUSQ7ACWVKIAAAAF2HF2OBRA] FLOAT , [XX_SOZQ6VWYIXYLKAAAAF2HF2OBRE] SMALLINT , [XX_OJQL3RHXQQDSYAAAAF2HF2OBRM] FLOAT , [XX_CV6VD6LV6E3PSAAAAF2HF2OBRQ] INTEGER , [XX_GJCNOA2DUIUYAAAAAF2HF2OBRU] INTEGER , [XX_ZF2DHGHCPU4EIAAAAF2HF2OBR4] FLOAT , [XX_M6CVIXN4QGB6CAAAAF2HF2OBSA] FLOAT , [XX_TQGTMZM56QDD6AAAAF2HF2OBSI] FLOAT , [XX_66IZL6GZB4KAIAAAAF2HF2OBSM] FLOAT , [XX_LBCELFXRUQAUUAAAAF2HF2OBSU] FLOAT , [XX_LBXHCO7Z4XOZEAAAAF2HF2OBSY] FLOAT , [XX_TU3FDZFRR55POAAAAF2HF2OBTA] FLOAT , [XX_UYHBKUQ5AY2KMAAAAF2HF2OBTE] FLOAT , [XX_VTBP4DD6HYUI2AAAAF2HF2OBTM] FLOAT , [XX_QAH77KJEHPMFEAAAAF2HF2OBTQ] FLOAT , [XX_44DVWTTDLJSYMAAAAF2HF2OBTU] FLOAT , [XX_V3NQA45HHTORUAAAAF2HF2OBTY] FLOAT , [XX_V3B3L3YSYRDBCAAAAF2HF2OBUA] FLOAT , [XX_XNBU6K5BZNTXMAAAAF2HF2OBUE] FLOAT , [XX_EL7HDOMHAR4ZAAAAAF2HF2OBUM] FLOAT , [XX_DAXK6C2NMQ3FKAAAAF2HF2OBUQ] FLOAT , [XX_SJ27M6MLJD6RWAAAAF2HF2OBUU] FLOAT , [XX_HHUKHDY5IP6ZKAAAAF2HF2OBU4] FLOAT , [XX_ZWZ2ZAMCKWO7YAAAAF2HF2OBVA] FLOAT , [XX_7MMLJ7JCZWIIYAAAAF2HF2OBVI] FLOAT , [XX_QTJASJOJCJGDCAAAAF2HF2OBVM] FLOAT , [XX_7OGMJXAXTLOIEAAAAF2HF2OBVU] FLOAT , [XX_VZD2WQB4UE6O4AAAAF2HF2OBVY] INTEGER , [XX_HFEXE5PJYKZTIAAAAF2HF2OBV4] FLOAT , [XX_RREYPK57E3ORQAAAAF2HF2OBWE] SMALLINT , [XX_ACJI6WPODVSVGAAAAF2HF2OBWI] FLOAT , [XX_I2LCLSYRVWJ4UAAAAF2HF2OBWM] INTEGER , [XX_OPO2HXGLSIWQGAAAAF2HF2OBWU] INTEGER , [XX_G256YA74Z5KNIAAAAF2HF2OBWY] FLOAT , [XX_LDQIHE6JW5UFYAAAAF2HF2OBXA] FLOAT , [XX_6UWHYPUNB4BTOAAAAF2HF2OBXE] FLOAT , [XX_RQW7DW3MJ6R62AAAAF2HF2OBXI] FLOAT , [XX_5WXSA2A3BOR2UAAAAF2HF2OBXM] FLOAT , [XX_PEJFMUJMNV2TIAAAAF2HF2OBXQ] FLOAT , [XX_YICEN4PS65PRQAAAAF2HF2OBXU] FLOAT , [XX_G6RICWNPJASSOAAAAF2HF2OBXY] FLOAT , [XX_BHGA6UFR7RKSAAAAAF2HF2OBX4] FLOAT , [XX_P4XIBHASBMVK4AAAAF2HF2OBYA] FLOAT , [XX_B4A6M7W3PE7JIAAAAF2HF2OBYE] FLOAT , [XX_N6FIHAOBFJ2SMAAAAF2HF2OBYM] FLOAT , [XX_72PTG553H7P7UAAAAF2HF2OBYU] FLOAT , [XX_J7P47O6ZAWDN6AAAAF2HF2OBY4] FLOAT , [XX_UU3RHPLFH5GA4AAAAF2HF2OBZE] FLOAT , [XX_YX34LPJ44NPZ6AAAAF2HF2OBZM] FLOAT , [XX_G6OSPVEGIP3D4AAAAF2HF2OBZY] FLOAT , [XX_WUZPKPDISE3R4AAAAF2HF2OB2A] FLOAT , [XX_27UW7R6EW6KS2AAAAF2HF2OB2I] FLOAT , [XX_5CPEDMUAFYDYQAAAAF2HF2OB2Q] FLOAT , [XX_P5VTPINDRLKTAAAAAF2HF2OB2Y] FLOAT , [XX_47MBNY2I5TT74AAAAF2HF2OB3A] FLOAT , [XX_WZORH5RUWLNNIAAAAF2HF2OB3I] INTEGER , [XX_3K322TME3A3RKAAAAF2HF2OB3Q] FLOAT , [XX_BJV64WDL4SKVMAAAAF2HF2OB3Y] SMALLINT , [XX_FPUF5O5C36KVKAAAAF2HF2OB34] FLOAT , [XX_QVRSDYMNO7QSSAAAAF2HF2OB4E] INTEGER , [XX_V3VQVNWTXKX3WAAAAF2HF2OB4M] INTEGER , [XX_PWH2PMAITR5HIAAAAF2HF2OB4U] FLOAT , [XX_NIXYWDS3NLNDOAAAAF2HF2OB44] FLOAT )] 
   1.360 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.361 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] open [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307][1] 
   1.362 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.363 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.364 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.365 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] initialValue() [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.366 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.367 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] connect [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.368 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] State is CLOSED, updating to READY 
   1.369 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] State is READY, initialising Connection 
   1.370 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] With user/pass 
   1.371 +2020-09-09 12:49:16,499 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] connecting .... 
   1.372 +2020-09-09 12:49:16,503 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] .... connected 
   1.373 +2020-09-09 12:49:16,518 DEBUG [FireThornTaskExecutor-40] [SQLServerOperator] SQL result [0] 
   1.374 +2020-09-09 12:49:16,518 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.375 +2020-09-09 12:49:16,518 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] close [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307][1] 
   1.376 +2020-09-09 12:49:16,518 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] operator() for [mssql] 
   1.377 +2020-09-09 12:49:16,518 DEBUG [FireThornTaskExecutor-40] [JdbcConnectionEntity] get() [jdbc:jtds:sqlserver://ramses2/LIVEFirethornUserdataULOV20190307] 
   1.378 +2020-09-09 12:49:16,518 INFO  [FireThornTaskExecutor-40] [AdqlQueryTimings] TIMING - jdbcdone() 
   1.379 +2020-09-09 12:49:16,523 DEBUG [FireThornTaskExecutor-40] [AdqlQueryTimings] AdqlQueryTimings() 
   1.380 +2020-09-09 12:49:16,532 DEBUG [FireThornTaskExecutor-32] [BlueQueryEntity] before refresh() 
   1.381 +2020-09-09 12:49:16,536 DEBUG [FireThornTaskExecutor-32] [AdqlQueryTimings] AdqlQueryTimings() 
   1.382 +2020-09-09 12:49:16,536 DEBUG [FireThornTaskExecutor-32] [AdqlQueryTimings] AdqlQueryTimings() 
   1.383 +2020-09-09 12:49:16,537 DEBUG [FireThornTaskExecutor-32] [BlueQueryEntity] after refresh() 
   1.384 +2020-09-09 12:49:16,537 DEBUG [FireThornTaskExecutor-32] [BlueQueryEntity] Getting base BaseResource 
   1.385 +2020-09-09 12:49:16,537 DEBUG [FireThornTaskExecutor-32] [BlueQueryEntity] Found base BaseResource [VVV JDBC] 
   1.386 +2020-09-09 12:49:16,537 DEBUG [FireThornTaskExecutor-32] [BlueQueryEntity] Getting direct resource 
   1.387 +2020-09-09 12:49:16,537 DEBUG [FireThornTaskExecutor-32] [OgsaJdbcResourceEntity$EntityFactory] primary(JdbcResource) [59] 
   1.388 +2020-09-09 12:49:16,538 DEBUG [FireThornTaskExecutor-32] [OgsaServiceEntity] primary() 
   1.389 +2020-09-09 12:49:16,542 DEBUG [FireThornTaskExecutor-32] [OgsaJdbcResourceEntity$EntityFactory] primary(OgsaService, JdbcResource) [847552][59] 
   1.390 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaJdbcResourceEntity$EntityFactory] Found primary OgsaJdbcResource [4785931] 
   1.391 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaJdbcResourceEntity$EntityFactory] Checking ogsaid ... 
   1.392 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] ogsaid [ACTIVE][ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.393 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] scan for [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.394 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] scantest() 
   1.395 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   name   [XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.396 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ident  [4785931] 
   1.397 +2020-09-09 12:49:16,546 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.398 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] prevscan   [2020-09-09T12:22:12.664Z] 
   1.399 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] start time [2020-09-08T20:53:54.993Z] 
   1.400 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] scantest for [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.401 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [OgsaJdbcResourceEntity] factory() 
   1.402 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity$EntityFactory] scanperiod() 
   1.403 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity$EntityFactory]   value [PT11M] 
   1.404 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] Factory scanperiod  [PT11M] 
   1.405 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] prevscan   [2020-09-09T12:22:12.664Z] 
   1.406 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] scanperiod [PT11M] 
   1.407 +2020-09-09 12:49:16,547 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] scan period expired - scanning 
   1.408 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.409 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] No existing lock found [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.410 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] Adding new lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.411 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [BaseComponentEntity] Running scan [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.412 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] scanimpl() 
   1.413 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   name   [XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.414 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ident  [4785931] 
   1.415 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.416 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] ping() 
   1.417 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   name   [XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.418 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ident  [4785931] 
   1.419 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.420 +2020-09-09 12:49:16,549 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] Service request [4785931][http://jarmila:8080/ogsadai/services/dataResources/ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.421 +
   1.422 +
   1.423 +
   1.424 +..
   1.425 +
   1.426 +
   1.427 +# Try again, but follow FT output 
   1.428 +
   1.429 +# Try with CURL
   1.430 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1000000+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.431 +*   Trying 129.215.175.100...
   1.432 +* TCP_NODELAY set
   1.433 +* Connected to tap.roe.ac.uk (129.215.175.100) port 80 (#0)
   1.434 +> GET /vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1000000+*+from+VHSDR6.vhsSource&LANG=ADQL HTTP/1.1
   1.435 +> Host: tap.roe.ac.uk
   1.436 +> User-Agent: curl/7.58.0
   1.437 +> Accept: */*
   1.438 +> 
   1.439 +
   1.440 +
   1.441 +
   1.442 +
   1.443 +# FT logs:
   1.444 +..
   1.445 +2020-09-09 12:49:16,548 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity]   ogsaid [ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1] 
   1.446 +2020-09-09 12:49:16,549 DEBUG [FireThornTaskExecutor-32] [OgsaBaseResourceEntity] Service request [4785931][http://jarmila:8080/ogsadai/services/dataResources/ogsadai-b39cde91-5008-4119-8fb6-77f411c045e1]
   1.447 +..
   1.448 +
   1.449 +
   1.450 +
   1.451 +# ---------------------------------------------
   1.452 +
   1.453 +# Try a simple query again to see if the service is working still
   1.454 +
   1.455 +
   1.456 +# Query: Select top 1 * from VHSDR6.vhsSource
   1.457 +
   1.458 +
   1.459 +# Try with CURL
   1.460 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.461 +*   Trying 129.215.175.100...
   1.462 +* TCP_NODELAY set
   1.463 +* Connected to tap.roe.ac.uk (129.215.175.100) port 80 (#0)
   1.464 +> GET /vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+*+from+VHSDR6.vhsSource&LANG=ADQL HTTP/1.1
   1.465 +> Host: tap.roe.ac.uk
   1.466 +> User-Agent: curl/7.58.0
   1.467 +> Accept: */*
   1.468 +> 
   1.469 +
   1.470 +# Hangs..
   1.471 +
   1.472 +
   1.473 +# Check OGSADAI Logs:
   1.474 +
   1.475 +2020-09-09 12:31:19,732 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:218]   State [RUNNING]
   1.476 +2020-09-09 12:31:19,732 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4797050]
   1.477 +2020-09-09 12:31:19,733 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:226] After callback
   1.478 +
   1.479 +
   1.480 +
   1.481 +
   1.482 +2020-09-09 12:56:42,728 DEBUG context.RequestContextFactory [http-nio-8080-exec-3,createContext:62] createContext(HttpServletRequest)
   1.483 +2020-09-09 12:56:42,728 DEBUG context.RequestContextFactory [http-nio-8080-exec-3,createContext:64] remote [10.0.0.2]
   1.484 +
   1.485 +
   1.486 +# Try again and check logs
   1.487 +# Query: Select top 1 * from VHSDR6.vhsSource
   1.488 +# Check OGSADAI Logs:
   1.489 +
   1.490 +
   1.491 +2020-09-09 12:31:19,732 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4797050]
   1.492 +2020-09-09 12:31:19,733 DEBUG blue.CallbackHandler [pool-1-thread-173,callback:226] After callback
   1.493 +2020-09-09 12:56:42,728 DEBUG context.RequestContextFactory [http-nio-8080-exec-3,createContext:62] createContext(HttpServletRequest)
   1.494 +2020-09-09 12:56:42,728 DEBUG context.RequestContextFactory [http-nio-8080-exec-3,createContext:64] remote [10.0.0.2]
   1.495 +2020-09-09 12:58:25,758 DEBUG context.RequestContextFactory [http-nio-8080-exec-2,createContext:62] createContext(HttpServletRequest)
   1.496 +2020-09-09 12:58:25,759 DEBUG context.RequestContextFactory [http-nio-8080-exec-2,createContext:64] remote [10.0.0.2]
   1.497 +
   1.498 +
   1.499 +
   1.500 +# So new createContext is called for each incoming query, but nothing happens after
   1.501 +# Ogsadai logs stop there, and FT logs only show system info checks
   1.502 +# Curl request hang..
   1.503 +
   1.504 +
   1.505 +# curl http://tap.roe.ac.uk/osa/tables
   1.506 +# Works fine
   1.507 +# So new queries are hanging, FT still works, but query mechanism is either not working, or queries are getting stuck in queue
   1.508 +
   1.509 +
   1.510 +# Run simple query again (SELECT TOP 1 * from ATLASDR1 Filter) and follow FT logs when creating new queries, match "query" keyword
   1.511 +
   1.512 +tail -f -n 1000 firethorn-debug.log | grep -C 5  "query"
   1.513 +
   1.514 +2020-09-09 13:06:46,777 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.515 +2020-09-09 13:06:46,777 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.516 +2020-09-09 13:06:46,777 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.517 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug] Request properties 
   1.518 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   requestURL  [http://tap.roe.ac.uk/firethorn/tap/54/sync] 
   1.519 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   queryString [REQUEST=doQuery&QUERY=SELECT+TOP+1+*+from+ATLASDR1.Filter&LANG=ADQL] 
   1.520 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   authType    [null] 
   1.521 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   remoteAddr  [10.255.0.2] 
   1.522 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug] Request headers 
   1.523 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   [host][tap.roe.ac.uk] 
   1.524 +2020-09-09 13:06:46,869 DEBUG [main-interface-10] [HttpRequestDebug]   [upgrade-insecure-requests][1] 
   1.525 +--
   1.526 +2020-09-09 13:06:46,944 DEBUG [FireThornTaskExecutor-61] [BlueQueryEntity] prepare() [null][EDITING] 
   1.527 +2020-09-09 13:06:46,944 DEBUG [FireThornTaskExecutor-61] [AdqlQueryTimings] AdqlQueryTimings() 
   1.528 +2020-09-09 13:06:46,944 INFO  [FireThornTaskExecutor-61] [AdqlQueryTimings] TIMING - adqlstart() 
   1.529 +2020-09-09 13:06:46,944 DEBUG [FireThornTaskExecutor-61] [MySearchTableList] MySearchTableList(AdqlResource, AdqlParserTable.Factory, AdqlQuery.Mode) 
   1.530 +2020-09-09 13:06:46,944 DEBUG [FireThornTaskExecutor-61] [MySearchTableList] MySearchTableList(AdqlResource, AdqlParserTable.Factory, AdqlQuery.Mode) 
   1.531 +2020-09-09 13:06:46,944 DEBUG [FireThornTaskExecutor-61] [BlueQueryEntity] Processing as [DIRECT] query 
   1.532 +2020-09-09 13:06:46,945 DEBUG [FireThornTaskExecutor-61] [MySearchTableList] search(ADQLTable) 
   1.533 +2020-09-09 13:06:46,945 DEBUG [FireThornTaskExecutor-61] [MySearchTableList]   target [null][ATLASDR1][Filter] 
   1.534 +2020-09-09 13:06:46,945 DEBUG [FireThornTaskExecutor-61] [MySearchTableList] search schema [ATLASDR1] 
   1.535 +2020-09-09 13:06:46,945 DEBUG [FireThornTaskExecutor-61] [AdqlResourceEntity] schemas() for [54][OSA ADQL resource] 
   1.536 +2020-09-09 13:06:46,945 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity] scan for [54][OSA ADQL resource] 
   1.537 +--
   1.538 +2020-09-09 13:06:46,963 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity] scanperiod [PT25H] 
   1.539 +2020-09-09 13:06:46,963 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity] prev scan is recent - skipping 
   1.540 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ADQLQuery) 
   1.541 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.542 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.543 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.ClauseSelect] 
   1.544 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.545 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ClauseSelect 
   1.546 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ClauseSelect) 
   1.547 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  Select item ---- 
   1.548 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]   name  [*] 
   1.549 +2020-09-09 13:06:46,966 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]   alias [null] 
   1.550 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]   class [adql.query.SelectAllColumns] 
   1.551 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, SelectAllColumns) 
   1.552 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] fields(AdqlParserQuery, ADQLQuery) 
   1.553 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]   ADQLQuery [{ADQL query}] 
   1.554 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlParserTableImpl] Iterator<DBColumn> iterator() 
   1.555 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [AdqlTableEntity] columns() for [5272][ATLASDR1.Filter] 
   1.556 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity] scan for [5272][Filter] 
   1.557 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity] scantest for [5272][Filter] 
   1.558 +2020-09-09 13:06:46,967 DEBUG [FireThornTaskExecutor-61] [BaseComponentEntity$EntityFactory] scanperiod() 
   1.559 +--
   1.560 +2020-09-09 13:06:46,991 DEBUG [FireThornTaskExecutor-61] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.561 +2020-09-09 13:06:46,991 DEBUG [FireThornTaskExecutor-61] [JdbcColumnEntity$EntityListener]  ident [5471] 
   1.562 +2020-09-09 13:06:46,991 DEBUG [FireThornTaskExecutor-61] [JdbcColumnEntity$EntityListener]  name  [isSectioned] 
   1.563 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [BlueQueryEntity] add(SelectField) [isSectioned][0][BYTE] 
   1.564 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.565 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.from.ADQLTable] 
   1.566 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.567 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLTable [Filter] 
   1.568 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ADQLTable) 
   1.569 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]    ---- 
   1.570 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]    AdqlTable [ATLASDR1.Filter] 
   1.571 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]    BaseTable [ATLASDR1.dbo.Filter] 
   1.572 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]    RootTable [ATLASDR1.dbo.Filter] 
   1.573 +2020-09-09 13:06:46,992 DEBUG [FireThornTaskExecutor-61] [BlueQueryEntity] add(AdqlTable) [5272][Filter] 
   1.574 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [BlueQueryEntity] add(BaseResource) [53][OSA JDBC] 
   1.575 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.576 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.ClauseConstraints] 
   1.577 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.578 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.579 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.ClauseADQL] 
   1.580 +2020-09-09 13:06:46,994 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.581 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.582 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.ClauseConstraints] 
   1.583 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.584 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ---- 
   1.585 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl]  ADQLObject [adql.query.ClauseADQL] 
   1.586 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.587 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [JdbcConnectionEntity] translator() for [mssql] 
   1.588 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [SQLServerTranslator] translate(ADQLQuery) 
   1.589 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [SQLServerTranslator] translate(ClauseSelect) 
   1.590 +2020-09-09 13:06:46,995 DEBUG [FireThornTaskExecutor-61] [AdqlParserTableImpl] Iterator<DBColumn> iterator() 
   1.591 +--
   1.592 +2020-09-09 13:06:47,048 DEBUG [FireThornTaskExecutor-59] [BlueTaskEntity]   state [READY] 
   1.593 +2020-09-09 13:06:47,048 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] prepare() [4850807][READY] 
   1.594 +2020-09-09 13:06:47,048 INFO  [FireThornTaskExecutor-59] [AdqlQueryTimings] TIMING - adqlstart() 
   1.595 +2020-09-09 13:06:47,048 DEBUG [FireThornTaskExecutor-59] [MySearchTableList] MySearchTableList(AdqlResource, AdqlParserTable.Factory, AdqlQuery.Mode) 
   1.596 +2020-09-09 13:06:47,048 DEBUG [FireThornTaskExecutor-59] [MySearchTableList] MySearchTableList(AdqlResource, AdqlParserTable.Factory, AdqlQuery.Mode) 
   1.597 +2020-09-09 13:06:47,048 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] Processing as [DIRECT] query 
   1.598 +2020-09-09 13:06:47,049 DEBUG [FireThornTaskExecutor-59] [MySearchTableList] search(ADQLTable) 
   1.599 +2020-09-09 13:06:47,049 DEBUG [FireThornTaskExecutor-59] [MySearchTableList]   target [null][ATLASDR1][Filter] 
   1.600 +2020-09-09 13:06:47,049 DEBUG [FireThornTaskExecutor-59] [MySearchTableList] search schema [ATLASDR1] 
   1.601 +2020-09-09 13:06:47,051 DEBUG [FireThornTaskExecutor-59] [AdqlResourceEntity] schemas() for [54][OSA ADQL resource] 
   1.602 +2020-09-09 13:06:47,051 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity] scan for [54][OSA ADQL resource] 
   1.603 +--
   1.604 +2020-09-09 13:06:47,067 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity] scanperiod [PT25H] 
   1.605 +2020-09-09 13:06:47,067 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity] prev scan is recent - skipping 
   1.606 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ADQLQuery) 
   1.607 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.608 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.609 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.ClauseSelect] 
   1.610 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.611 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ClauseSelect 
   1.612 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ClauseSelect) 
   1.613 +2020-09-09 13:06:47,073 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  Select item ---- 
   1.614 +2020-09-09 13:06:47,074 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]   name  [*] 
   1.615 +2020-09-09 13:06:47,074 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]   alias [null] 
   1.616 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]   class [adql.query.SelectAllColumns] 
   1.617 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, SelectAllColumns) 
   1.618 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] fields(AdqlParserQuery, ADQLQuery) 
   1.619 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]   ADQLQuery [{ADQL query}] 
   1.620 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlParserTableImpl] Iterator<DBColumn> iterator() 
   1.621 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [AdqlTableEntity] columns() for [5272][ATLASDR1.Filter] 
   1.622 +2020-09-09 13:06:47,075 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity] scan for [5272][Filter] 
   1.623 +2020-09-09 13:06:47,076 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity] scantest for [5272][Filter] 
   1.624 +2020-09-09 13:06:47,076 DEBUG [FireThornTaskExecutor-59] [BaseComponentEntity$EntityFactory] scanperiod() 
   1.625 +--
   1.626 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [JdbcColumnEntity$EntityListener] load(JdbcColumnEntity) 
   1.627 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [JdbcColumnEntity$EntityListener]  ident [5471] 
   1.628 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [JdbcColumnEntity$EntityListener]  name  [isSectioned] 
   1.629 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] add(SelectField) [isSectioned][0][BYTE] 
   1.630 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.631 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.from.ADQLTable] 
   1.632 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.633 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLTable [Filter] 
   1.634 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, ADQLTable) 
   1.635 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]    ---- 
   1.636 +2020-09-09 13:06:47,098 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]    AdqlTable [ATLASDR1.Filter] 
   1.637 +2020-09-09 13:06:47,099 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]    BaseTable [ATLASDR1.dbo.Filter] 
   1.638 +2020-09-09 13:06:47,099 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]    RootTable [ATLASDR1.dbo.Filter] 
   1.639 +2020-09-09 13:06:47,099 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] add(AdqlTable) [5272][Filter] 
   1.640 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] add(BaseResource) [53][OSA JDBC] 
   1.641 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.642 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.ClauseConstraints] 
   1.643 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.644 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.645 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.ClauseADQL] 
   1.646 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.647 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.648 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.ClauseConstraints] 
   1.649 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.650 +2020-09-09 13:06:47,100 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ---- 
   1.651 +2020-09-09 13:06:47,101 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl]  ADQLObject [adql.query.ClauseADQL] 
   1.652 +2020-09-09 13:06:47,101 DEBUG [FireThornTaskExecutor-59] [AdqlParserImpl] process(AdqlParserQuery, ADQLQuery, Iterable<ADQLObject>) 
   1.653 +2020-09-09 13:06:47,101 DEBUG [FireThornTaskExecutor-59] [JdbcConnectionEntity] translator() for [mssql] 
   1.654 +2020-09-09 13:06:47,102 DEBUG [FireThornTaskExecutor-59] [SQLServerTranslator] translate(ADQLQuery) 
   1.655 +2020-09-09 13:06:47,102 DEBUG [FireThornTaskExecutor-59] [SQLServerTranslator] translate(ClauseSelect) 
   1.656 +2020-09-09 13:06:47,102 DEBUG [FireThornTaskExecutor-59] [AdqlParserTableImpl] Iterator<DBColumn> iterator() 
   1.657 +--
   1.658 +2020-09-09 13:06:47,113 DEBUG [FireThornTaskExecutor-59] [BlueTaskEntity]   state [READY] 
   1.659 +2020-09-09 13:06:47,113 DEBUG [FireThornTaskExecutor-59] [BlueTaskEntity] Before execute() 
   1.660 +2020-09-09 13:06:47,113 DEBUG [FireThornTaskExecutor-59] [BlueTaskEntity]   state [READY] 
   1.661 +2020-09-09 13:06:47,113 DEBUG [FireThornTaskExecutor-59] [BlueQueryEntity] execute() [4850807][READY] 
   1.662 +2020-09-09 13:06:47,114 DEBUG [FireThornTaskExecutor-59] [BlueTaskLogEntity] LogEntryEntity() 
   1.663 +2020-09-09 13:06:47,114 DEBUG [FireThornTaskExecutor-59] [BlueTaskLogEntity]   task    [entity[class[uk.ac.roe.wfau.firethorn.adql.query.blue.BlueQueryEntity] ident[4850807]]] 
   1.664 +2020-09-09 13:06:47,115 DEBUG [FireThornTaskExecutor-59] [BlueTaskLogEntity]   level   [INFO] 
   1.665 +2020-09-09 13:06:47,115 DEBUG [FireThornTaskExecutor-59] [BlueTaskLogEntity]   source  [uk.ac.roe.wfau.firethorn.adql.query.blue.BlueTaskLogEntity$EntityFactory] 
   1.666 +2020-09-09 13:06:47,115 DEBUG [FireThornTaskExecutor-59] [BlueTaskLogEntity]   message [Executing query] 
   1.667 +2020-09-09 13:06:47,118 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.668 +2020-09-09 13:06:47,118 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.669 +2020-09-09 13:06:47,118 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.670 +2020-09-09 13:06:47,150 DEBUG [FireThornTaskExecutor-59] [BlueTaskEntity$TaskRunner] thread(Updator) [4850807] 
   1.671 +2020-09-09 13:06:47,151 DEBUG [FireThornTaskExecutor-64] [BlueTaskEntity$TaskRunner] future(Updator) [4850807] 
   1.672 +
   1.673 +
   1.674 +# Check latest FT logs without keyword match:
   1.675 +
   1.676 +2020-09-09 13:09:38,776 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.677 +2020-09-09 13:09:38,925 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.678 +2020-09-09 13:09:38,925 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.679 +2020-09-09 13:09:38,925 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.680 +2020-09-09 13:09:39,276 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.681 +2020-09-09 13:09:39,276 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.682 +2020-09-09 13:09:39,276 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.683 +2020-09-09 13:09:39,425 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.684 +2020-09-09 13:09:39,425 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.685 +2020-09-09 13:09:39,425 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.686 +2020-09-09 13:09:39,776 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.687 +2020-09-09 13:09:39,777 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.688 +2020-09-09 13:09:39,777 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.689 +2020-09-09 13:09:39,926 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.690 +2020-09-09 13:09:39,926 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.691 +2020-09-09 13:09:39,926 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.692 +2020-09-09 13:09:40,277 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.693 +2020-09-09 13:09:40,277 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.694 +2020-09-09 13:09:40,277 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.695 +2020-09-09 13:09:40,426 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.696 +2020-09-09 13:09:40,426 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.697 +2020-09-09 13:09:40,426 DEBUG [FireThornTaskExecutor-39] [BaseComponentEntity] Waiting on lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.698 +2020-09-09 13:09:40,777 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Checking for existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM] 
   1.699 +2020-09-09 13:09:40,778 DEBUG [FireThornTaskExecutor-49] [BaseComponentEntity] Found existing lock [4785931][XX_Y7CKNTMFTETACAAAAF2HAPXHYM][2020-09-09T12:49:16.548Z] 
   1.700 +
   1.701 +
   1.702 +
   1.703 +# Seems to be stuck
   1.704 +
   1.705 +
   1.706 +
   1.707 +# --------------------------------------------
   1.708 +
   1.709 +# After aprox. one hour simple queries start working again, but all the ones that were hanging
   1.710 +
   1.711 +# Check Containers
   1.712 +
   1.713 +[Stevedore@Araybwyn ~]$ docker ps
   1.714 +CONTAINER ID        IMAGE                           COMMAND                  CREATED             STATUS                       PORTS               NAMES
   1.715 +4f999370d506        firethorn/firethorn:2.1.36      "/bin/sh -c '/var/lo…"   About an hour ago   Up About an hour (healthy)   8080/tcp            ft_gillian.1.nakc60mxdc1lx9v72aj6nm6hl
   1.716 +4fece98eb050        firethorn/ogsadai:2.1.36        "/bin/sh -c '/var/lo…"   About an hour ago   Up About an hour (healthy)   8080/tcp            ft_jarmila.1.yd6m68dtl198p6rrfbf4ni3y1
   1.717 +bff3f7d8343e        firethorn/postgres:2.1.36       "docker-entrypoint.s…"   11 days ago         Up 11 days                   5432/tcp            ft_carolina.1.kq9krov9tvlt1tvtyhvgi6xbd
   1.718 +2d1c14fa2631        firethorn/postgres:2.1.36       "docker-entrypoint.s…"   11 days ago         Up 11 days                   5432/tcp            ft_bethany.1.4o8yg7e9zhuf404vhz2m8yt68
   1.719 +fa88eb69066f        firethorn/firethorn-py:latest   "python3"                11 days ago         Up 11 days                                       ft_firethorn-py.1.sdusyp77tns4g2nouo0wi3v9k
   1.720 +
   1.721 +# Service restarted themselves after healthchecker failed
   1.722 +
   1.723 +
   1.724 +
   1.725 +# --------------------------------------------
   1.726 +
   1.727 +# Check a simple query
   1.728 +
   1.729 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+sourceID+from+VHSDR6.vhsSource&LANG=ADQL"
   1.730 +*   Trying 129.215.175.100...
   1.731 +* TCP_NODELAY set
   1.732 +* Connected to tap.roe.ac.uk (129.215.175.100) port 80 (#0)
   1.733 +> GET /vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+sourceID+from+VHSDR6.vhsSource&LANG=ADQL HTTP/1.1
   1.734 +> Host: tap.roe.ac.uk
   1.735 +> User-Agent: curl/7.58.0
   1.736 +> Accept: */*
   1.737 +> 
   1.738 +< HTTP/1.1 303 
   1.739 +< Date: Wed, 09 Sep 2020 14:37:47 GMT
   1.740 +< Server: Apache/2.4.34 (Fedora)
   1.741 +< X-Clacks-Overhead: GNU Terry Pratchett
   1.742 +< Location: http://tap.roe.ac.uk/firethorn/adql/table/4857605/votable
   1.743 +< firethorn.auth.identity: http://tap.roe.ac.uk/firethorn/community-member/4858482
   1.744 +< firethorn.auth.username: anon-6MCKRUMGDMMMQAAAAF2HGTITL4
   1.745 +< firethorn.auth.community: friends
   1.746 +< Content-Type: text/xml;charset=ISO-8859-1
   1.747 +< Content-Length: 67
   1.748 +< 
   1.749 +* Ignoring the response-body
   1.750 +* Connection #0 to host tap.roe.ac.uk left intact
   1.751 +* Issue another request to this URL: 'http://tap.roe.ac.uk/firethorn/adql/table/4857605/votable'
   1.752 +* Found bundle for host tap.roe.ac.uk: 0x564923e8ca50 [can pipeline]
   1.753 +* Re-using existing connection! (#0) with host tap.roe.ac.uk
   1.754 +* Connected to tap.roe.ac.uk (129.215.175.100) port 80 (#0)
   1.755 +> GET /firethorn/adql/table/4857605/votable HTTP/1.1
   1.756 +> Host: tap.roe.ac.uk
   1.757 +> User-Agent: curl/7.58.0
   1.758 +> Accept: */*
   1.759 +> 
   1.760 +< HTTP/1.1 200 
   1.761 +< Date: Wed, 09 Sep 2020 14:37:47 GMT
   1.762 +< Server: Apache/2.4.34 (Fedora)
   1.763 +< X-Clacks-Overhead: GNU Terry Pratchett
   1.764 +< firethorn.auth.identity: http://tap.roe.ac.uk/firethorn/community-member/4858485
   1.765 +< firethorn.auth.username: anon-JNE4XFFL57ISIAAAAF2HGTI6FQ
   1.766 +< firethorn.auth.community: friends
   1.767 +< Content-Type: text/xml;charset=UTF-8
   1.768 +< Content-Length: 747
   1.769 +< 
   1.770 +* Connection #0 to host tap.roe.ac.uk left intact
   1.771 +<?xml version='1.0' encoding='UTF-8'?><VOTABLE xmlns='http://www.ivoa.net/xml/VOTable/v1.3' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance' xsi:schemaLocation='http://www.ivoa.net/xml/VOTable/v1.3 http://www.ivoa.net/xml/VOTable/v1.3' version='1.3'><RESOURCE type='results'><INFO name='QUERY_STATUS' value='OK'></INFO><INFO name='link' value='http://tap.roe.ac.uk/firethorn/adql/table/4857605'/><TABLE ID='table.4857605' name='XX_6RVYMVMECDFYIAAAAF2HGTIUPM'><FIELD ID='column.4857673' name='sourceID' datatype='long'><LINK content-type='application/json' content-role='metadata' href='http://tap.roe.ac.uk/firethorn/adql/column/4857673'/></FIELD><DATA><TABLEDATA><TR><TD>472446402561</TD></TR></TABLEDATA></DATA></TABLE></RESOURCE></VOTABLE>
   1.772 +
   1.773 +
   1.774 +
   1.775 +
   1.776 +# ---------------------------------------------
   1.777 +
   1.778 +# Try some more queries
   1.779 +
   1.780 +# Query: Select top 1000000 * from VHSDR6.vhsSource
   1.781 +
   1.782 +
   1.783 +# Try with CURL
   1.784 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+1+*+from+VHSDR6.vhsSource&LANG=ADQL"
   1.785 + 
   1.786 +<TR><TD>472446642836</TD></TR><TR><TD>472
   1.787 +* transfer closed with outstanding read data remaining
   1.788 +* stopped the pause stream!
   1.789 +* Closing connection 0
   1.790 +curl: (18) transfer closed with outstanding read data remaining
   1.791 +
   1.792 +
   1.793 +# Apache logs:
   1.794 +        [Wed Sep 09 14:44:37.158441 2020] [proxy_http:error] [pid 926:tid 140532965680896] (20014)Internal error (specific information not available): [client 195.194.121.66:42850] AH01110: error reading response
   1.795 +
   1.796 +# OGSADAI logs:
   1.797 +..
   1.798 +	2020-09-09 14:44:32,428 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:215] Response bean
   1.799 +	2020-09-09 14:44:32,428 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:216]   Ident [4857405]
   1.800 +	2020-09-09 14:44:32,429 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:217]   Name  [XX_POECQ3QSSVVDOAAAAF2HGUVCBI]
   1.801 +	2020-09-09 14:44:32,429 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:218]   State [COMPLETED]
   1.802 +	2020-09-09 14:44:32,429 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:219]   Self  [http://gillian:8081/firethorn/blue/query/4857405]
   1.803 +	2020-09-09 14:44:32,429 DEBUG blue.CallbackHandler [pool-1-thread-17,callback:226] After callback
   1.804 +	2020-09-09 14:44:32,430 DEBUG activity.MatchedIterativeActivity [pool-1-thread-17,debug:84] performing last stage of processing
   1.805 +	2020-09-09 14:44:32,431 DEBUG activity.MatchedIterativeActivity [pool-1-thread-17,debug:84] performing clean-up
   1.806 +	2020-09-09 14:44:32,431 DEBUG event.LoggingActivityListener [pool-1-thread-17,debug:84] COMPLETED: Activity uk.ac.roe.wfau.firethorn.JdbcInsertData (instance name = uk.ac.roe.wfau.firethorn.JdbcInsertData-ogsadai-7fd8c885-8c1a-4d08-98ce-93cdf97b48e3)
   1.807 +	2020-09-09 14:44:32,432 DEBUG event.LoggingActivityListener [pool-1-thread-19,debug:84] COMPLETED: Activity uk.org.ogsadai.DeliverToRequestStatus (instance name = uk.org.ogsadai.DeliverToRequestStatus-ogsadai-71c29abf-bb0b-41bf-a34b-fae8985c3270)
   1.808 +
   1.809 +
   1.810 +# ---------------------------------------------
   1.811 +
   1.812 +# What are the max limits in our service?
   1.813 +# Check firethorn.properties
   1.814 +
   1.815 +...
   1.816 +firethorn.limits.rows.absolute=10000000
   1.817 +firethorn.limits.rows.default=1000000
   1.818 +..
   1.819 +
   1.820 +
   1.821 +# ---------------------------------------------
   1.822 +
   1.823 +# So what happens if we try 2 million rows
   1.824 +
   1.825 +curl -v -L "http://tap.roe.ac.uk/vsa/sync?REQUEST=doQuery&QUERY=SELECT+TOP+2000000+sourceID+from+VHSDR6.vhsSource&LANG=ADQL"
   1.826 +
   1.827 +> ..	
   1.828 +</TD></TR* Connection #0 to host tap.roe.ac.uk left intact
   1.829 +><TR><TD>472447450576</TD></TR><TR><TD>472447450577</TD></TR><TR><TD>472447450578</TD></TR><TR><TD>472447450579</TD></TR><TR><TD>472447450580</TD></TR><TR><TD>472447450581</TD></TR><TR><TD>472447450582</TD></TR><TR><TD>472447450583</TD></TR><TR><TD>472447450584</TD></TR><TR><TD>472447450585</TD></TR><TR><TD>472447450586</TD></TR><TR><TD>472447450587</TD></TR><TR><TD>472447450588</TD></TR><TR><TD>472447450589</TD></TR><TR><TD>472447450590</TD></TR><TR><TD>472447450591</TD></TR><TR><TD>472447450592</TD></TR><TR><TD>472447450593</TD></TR></TABLEDATA></DATA></TABLE><INFO name="QUERY_STATUS" value="OVERFLOW" /></RESOURCE></VOTABLE>
   1.830 +
   1.831 +# Success
   1.832 +# VOTable correctly gives us an overflow status
   1.833 +
   1.834 +## Check User database:
   1.835 +
   1.836 +SELECT 
   1.837 +  COUNT(*)
   1.838 +  FROM [LIVEFirethornUserdataULOV20190307].[dbo].[XX_UPJRKLTFGX7W4AAAAF2HGUVCZQ]
   1.839 +
   1.840 +  1000000
   1.841 +
   1.842 +# So our maxlimit is reached, and 1million rows are written to DB
   1.843 +
   1.844 +
   1.845 +
   1.846 +
   1.847 +# ---------------------------------------------
   1.848 +
   1.849 +
   1.850 +# After checking OGSADAI logs for older errors we see this one from Sep 08 2020:
   1.851 +
   1.852 +
   1.853 +2020-09-08 18:23:07,442 WARN  data.LimitsActivity [pool-1-thread-370,inner:487] Unknown Throwable during processing [java.lang.OutOfMemoryError][GC overhead limit exceeded]
   1.854 +2020-09-08 18:23:08,425 DEBUG data.LimitsActivity [pool-1-thread-370,inner:493] Finished inner
   1.855 +2020-09-08 18:23:08,425 DEBUG activity.MatchedIterativeActivity [pool-1-thread-370,debug:84] performing clean-up
   1.856 +2020-09-08 18:23:08,425 DEBUG event.LoggingActivityListener [pool-1-thread-370,debug:84] uk.org.ogsadai.activity.ActivityProcessingException: A problem has occured during activity processing.
   1.857 +	at uk.ac.roe.wfau.firethorn.ogsadai.activity.server.data.LimitsActivity.inner(LimitsActivity.java:488)
   1.858 +	at uk.ac.roe.wfau.firethorn.ogsadai.activity.server.data.LimitsActivity.processIteration(LimitsActivity.java:198)
   1.859 +	at uk.org.ogsadai.activity.MatchedIterativeActivity.process(MatchedIterativeActivity.java:90)
   1.860 +	at uk.org.ogsadai.activity.event.EventfulActivity.process(EventfulActivity.java:78)
   1.861 +	at uk.org.ogsadai.activity.concurrency.ActivityProcessingTask.call(ActivityProcessingTask.java:81)
   1.862 +	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
   1.863 +	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
   1.864 +	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
   1.865 +	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   1.866 +	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   1.867 +	at java.lang.Thread.run(Thread.java:748)
   1.868 +Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
   1.869 +
   1.870 +2020-09-08 18:23:08,426 WARN  event.LoggingActivityListener [pool-1-thread-370,warnExceptionAndChildren:343] #1599589388425:142130# A problem has occurred during processing of activity uk.ac.roe.wfau.firethorn.Limits with instance name uk.ac.roe.wfau.firethorn.Limits-ogsadai-3d458a9a-35dc-4fae-8635-d2fc1c125c4c.
   1.871 +2020-09-08 18:23:08,426 WARN  event.LoggingActivityListener [pool-1-thread-370,warnExceptionAndChildren:343] #1599589388425:142130# A problem has occured during activity processing.
   1.872 +2020-09-08 18:23:08,426 WARN  event.LoggingActivityListener [pool-1-thread-370,warnExceptionAndChildren:343] #1599589388425:142130# java.lang.OutOfMemoryError: GC overhead limit exceeded
   1.873 +2020-09-08 18:23:08,427 WARN  data.DelaysActivity [pool-1-thread-371,processIteration:178] PipeClosed during processing
   1.874 +2020-09-08 18:23:08,427 WARN  data.DelaysActivity [pool-1-thread-371,done:227] PipeClosed during done
   1.875 +2020-09-08 18:23:08,427 DEBUG activity.MatchedIterativeActivity [pool-1-thread-371,debug:84] performing last stage of processing
   1.876 +2020-09-08 18:23:08,427 DEBUG data.DelaysActivity [pool-1-thread-371,postprocess:198] postprocess()
   1.877 +2020-09-08 18:23:08,428 DEBUG activity.MatchedIterativeActivity [pool-1-thread-371,debug:84] performing clean-up
   1.878 +2020-09-08 18:23:08,428 DEBUG event.LoggingActivityListener [pool-1-thread-371,debug:84] COMPLETED: Activity uk.ac.roe.wfau.firethorn.Delays (instance name = uk.ac.roe.wfau.firethorn.Delays-ogsadai-c9e00f18-1011-4753-a000-9432c980e21b)
   1.879 +2020-09-08 18:23:11,403 ERROR sql.SQLQueryActivity [pool-1-thread-372,processIteration:345] Caught a Throwable, wrapping it in an ActivityProcessingException
   1.880 +2020-09-08 18:23:11,403 DEBUG activity.MatchedIterativeActivity [pool-1-thread-372,debug:84] performing clean-up
   1.881 +2020-09-08 18:23:11,403 DEBUG sql.SQLQueryActivity [pool-1-thread-372,cleanUp:482] cleanUp()
   1.882 +2020-09-08 18:23:11,403 DEBUG sql.SQLQueryActivity [pool-1-thread-372,cleanUp:486] Shutting down ExecutorService
   1.883 +2020-09-08 18:23:11,404 DEBUG sql.SQLQueryActivity [pool-1-thread-372,cleanUp:498] Closing Statement
   1.884 +2020-09-08 18:23:11,404 DEBUG sql.SQLQueryActivity [pool-1-thread-372,cleanUp:511] Releasing Connection
   1.885 +2020-09-08 18:23:11,404 DEBUG event.LoggingActivityListener [pool-1-thread-372,debug:84] uk.org.ogsadai.activity.ActivityProcessingException: A problem has occured during activity processing.
   1.886 +	at uk.ac.roe.wfau.firethorn.ogsadai.activity.server.sql.SQLQueryActivity.processIteration(SQLQueryActivity.java:346)
   1.887 +	at uk.org.ogsadai.activity.MatchedIterativeActivity.process(MatchedIterativeActivity.java:90)
   1.888 +	at uk.org.ogsadai.activity.event.EventfulActivity.process(EventfulActivity.java:78)
   1.889 +	at uk.org.ogsadai.activity.concurrency.ActivityProcessingTask.call(ActivityProcessingTask.java:81)
   1.890 +	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
   1.891 +	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
   1.892 +	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
   1.893 +	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   1.894 +	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   1.895 +	at java.lang.Thread.run(Thread.java:748)
   1.896 +Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
   1.897 +
   1.898 +