Failed to run sample python script


#1

Hi,

I tried the sample python scripts sample.py and sample2.py, and failed. The execution caused a hang after two queries.
Following is my log, please help me to figure out what’s the problem. Thanks!

-Feng


2012-07-31 14:31:42,251 [0x7f08e3b8c7c0] [DEBUG]: Waiting for the first message
2012-07-31 14:31:42,252 [0x7f08e3b8c7c0] [DEBUG]: Connection started from CLIENT (127.0.0.1)
2012-07-31 14:31:42,252 [0x7f08e3b6c700] [DEBUG]: Generated queryID: instanceID=0, time=1343770302, clock=0, nextID=0, queryID=1100855398078
2012-07-31 14:31:42,252 [0x7f08e3b6c700] [DEBUG]: Allocating query (1100855398078)
2012-07-31 14:31:42,252 [0x7f08e3b6c700] [DEBUG]: Number of allocated queries = 1
2012-07-31 14:31:42,274 [0x7f08e3b6c700] [DEBUG]: Initialized query (1100855398078)
2012-07-31 14:31:42,274 [0x7f08e3b6c700] [DEBUG]: Parsing query(1100855398078): drop array simplearray
2012-07-31 14:31:42,276 [0x7f08e3b6c700] [DEBUG]: Acquiring 1 array locks for query 1100855398078
2012-07-31 14:31:42,276 [0x7f08e3b6c700] [DEBUG]: Acquiring lock: Lock: arrayName=simplearray, arrayId=0, queryId=1100855398078, instanceId=0, instanceRole=COORD, lockMode=4, arrayVersion=0, arrayVersionId=0, timestamp=1
2012-07-31 14:31:42,276 [0x7f08e3b6c700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=simplearray, arrayId=0, queryId=1100855398078, instanceId=0, instanceRole=COORD, lockMode=4, arrayVersion=0, arrayVersionId=0, timestamp=1
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: Inferred schema for operator remove: simplearrayfoo:int32,bar:char,baz:string [a=0:99,10,0,b=0:9,10,0]
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: The query is prepared
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: Executing query(1100855398078): drop array simplearray
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: Creating Habilis optimizer instance
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: Query is optimized
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: The physical plan is detected as DML
2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]:
[pPlan]:

[pInstance] physicalRemove agg 0 ddl 0 tile 0 children 0
schema simplearrayfoo:int32,bar:char,baz:string [a=0:99,10,0,b=0:9,10,0]
props sgm 1 sgo 1
distr roro
bound start [0, 0] end [99, 9] density 1 cells 1000 chunks 10 est_bytes 96320

2012-07-31 14:31:42,278 [0x7f08e3b6c700] [DEBUG]: (Pre)Single executing queryID: 1100855398078
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Query is serialized: [pPlan]:

[pInstance] physicalRemove agg 0 ddl 0 tile 0 children 0
schema simplearrayfoo:int32,bar:char,baz:string [a=0:99,10,0,b=0:9,10,0]
props sgm 1 sgo 1
distr roro
bound start [0, 0] end [99, 9] density 1 cells 1000 chunks 10 est_bytes 96320

2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Prepare physical plan was sent out
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Waiting confirmation about preparing physical plan in queryID from 0 instances
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Execute physical plan was sent out
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [INFO ]: Executing query(1100855398078): drop array simplearray
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Request exclusive lock of array simplearray for query 1100855398078
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Granted exclusive lock of array simplearray for query 1100855398078
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: Query is executed locally
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: The responses are received
2012-07-31 14:31:42,279 [0x7f08e3b6c700] [DEBUG]: (Post)Single executing queryID: 1100855398078
2012-07-31 14:31:42,280 [0x7f08e3b6c700] [DEBUG]: The result of query is returned
2012-07-31 14:31:42,280 [0x7f08e3b6c700] [DEBUG]: The result of query is sent to the client
2012-07-31 14:31:42,281 [0x7f08d573e700] [DEBUG]: Generated queryID: instanceID=0, time=1343770302, clock=10000, nextID=1, queryID=1100855408079
2012-07-31 14:31:42,281 [0x7f08d573e700] [DEBUG]: Allocating query (1100855408079)
2012-07-31 14:31:42,281 [0x7f08d573e700] [DEBUG]: Number of allocated queries = 2
2012-07-31 14:31:42,281 [0x7f08d573e700] [DEBUG]: Initialized query (1100855408079)
2012-07-31 14:31:42,281 [0x7f08d573e700] [DEBUG]: Parsing query(1100855408079): CREATE immutable ARRAY simplearray < foo:int32, bar:char, baz:string > [ a=0:99, 10,0, b=0:9, 10,0]
2012-07-31 14:31:42,282 [0x7f08d573e700] [DEBUG]: Acquiring 1 array locks for query 1100855408079
2012-07-31 14:31:42,282 [0x7f08d573e700] [DEBUG]: Acquiring lock: Lock: arrayName=simplearray, arrayId=0, queryId=1100855408079, instanceId=0, instanceRole=COORD, lockMode=3, arrayVersion=0, arrayVersionId=0, timestamp=1
2012-07-31 14:31:42,282 [0x7f08d573e700] [DEBUG]: SystemCatalog::lockArray: Lock: arrayName=simplearray, arrayId=0, queryId=1100855408079, instanceId=0, instanceRole=COORD, lockMode=3, arrayVersion=0, arrayVersionId=0, timestamp=1
2012-07-31 14:33:21,007 [0x7f08e3b8c7c0] [WARN ]: Cancel client query 1100855398078 on disconnect
2012-07-31 14:33:21,008 [0x7f08e3b8c7c0] [WARN ]: Cancel client query 1100855408079 on disconnect
2012-07-31 14:33:21,008 [0x7f08d563d700] [DEBUG]: Query (1100855398078) is being aborted
2012-07-31 14:33:21,008 [0x7f08d563d700] [ERROR]: Query (1100855398078) error handlers (1) are being executed
2012-07-31 14:33:21,010 [0x7f08d563d700] [DEBUG]: Deallocating query (1100855398078)
2012-07-31 14:33:21,010 [0x7f08d563d700] [DEBUG]: Releasing locks for query 1100855398078
2012-07-31 14:33:21,010 [0x7f08d563d700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1100855398078
2012-07-31 14:33:21,011 [0x7f08d563d700] [DEBUG]: Release lock of array simplearray for query 1100855398078
2012-07-31 14:33:21,011 [0x7f08d563d700] [DEBUG]: Query (1100855408079) is being aborted
2012-07-31 14:33:21,011 [0x7f08d563d700] [DEBUG]: Query (1100855408079) is still in progress
2012-07-31 14:33:21,305 [0x7f08d573e700] [DEBUG]: Releasing locks for query 1100855408079
2012-07-31 14:33:21,305 [0x7f08d573e700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1100855408079
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Query::done: queryID=1100855408079, _commitState=2, erorCode=62
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Query (1100855408079) is being aborted
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Deallocating query (1100855408079)
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Releasing locks for query 1100855408079
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: SystemCatalog::deleteArrayLocks instanceId = 0 queryId = 1100855408079
2012-07-31 14:33:21,306 [0x7f08d573e700] [ERROR]: executeClientQuery failed to complete: SystemException in file: src/query/Query.cpp function: handleAbort line: 527
Error id: scidb::SCIDB_SE_QPROC::SCIDB_LE_QUERY_CANCELLED
Error description: Query processor error. Query 1100855408079 was cancelled.
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Query 1100855408079 is not found
2012-07-31 14:33:21,306 [0x7f08d573e700] [DEBUG]: Disconnected


#2

Feng,

This is most likely caused by a recent change to the client protocol – we now require the client to issue a completeQuery(). I believe the script didn’t get updated in 12.3.

Try the new example script (tests/harness/testcases/t/client/basic.py.in) from this source tar.gz from latest TRUNK.
p4-releases-12-7.s3.amazonaws.c … ire-m3.tgz

Note the completeQuery step after executeQuery.

Suchi