Skip to content

Instantly share code, notes, and snippets.

@antoniou

antoniou/agora_voting_election

Created July 23, 2015 09:59
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save antoniou/d2ab75568d166f045d0e to your computer and use it in GitHub Desktop.
Save antoniou/d2ab75568d166f045d0e to your computer and use it in GitHub Desktop.
Download ZIP
Raw
agora_voting_election
DEBUG:root:CREATE local TASK for action create_election with ID 7f86a661-516d-45fa-92f5-802c9a257131
/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/type_api.py:863: SAWarning: Unicode type received non-unicodebind param value.
return impl_processor(process_param(value, dialect))
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = 7f86a661-516d-45fa-92f5-802c9a257131
DEBUG:root:SENDING MESSAGE id 547145e7-410e-44f9-a4a8-0dd6f276342e with action create_election to https://auth1:443/api/queues/launch_task/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue launch_task
DEBUG:root:The MESSAGE is LOCAL and with id 547145e7-410e-44f9-a4a8-0dd6f276342e
INFO:root:adding job in sched for queue launch_task
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:12.349965)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/launch_task/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 2/1] 172.17.42.1 () {44 vars in 2578 bytes} [Thu Jul 23 08:01:12 2015] POST /api/queues/launch_task/ => generated 0 bytes in 26 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 2)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
[pid: 149|app: 0|req: 2/2] 172.17.42.1 () {44 vars in 2572 bytes} [Thu Jul 23 08:01:12 2015] POST /public_api/election => generated 15 bytes in 127 msecs (HTTP/1.1 202) 2 headers in 85 bytes (2 switches on core 0)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:12.349965)
DEBUG:root:EXEC ACTION handler for MESSAGE id 547145e7-410e-44f9-a4a8-0dd6f276342e (QUEUE launch_task)
DEBUG:root:EXEC TASK with id 7f86a661-516d-45fa-92f5-802c9a257131
killing previous vfork instances..
DEBUG:root:CREATE local SEQUENTIAL TASK with ID 6b3d4cc5-7f3a-4850-9080-060a6fc46e7a
DEBUG:root:CREATE local TASK for action generate_private_info with ID acf137c7-5af1-4bba-a3e4-b3d5cc40587e
DEBUG:root:CREATE local TASK for action generate_private_info with ID c2033b86-4e5d-4568-a8b5-c748936f0e30
DEBUG:root:CREATE local TASK for action merge_protinfo with ID 71f44130-a294-4370-a1b1-59c97cece8c4
DEBUG:root:CREATE local TASK for action return_election with ID da5a16ef-063c-4a0a-9ae9-ea55dfde506c
DEBUG:root:SENDING TASK acf137c7-5af1-4bba-a3e4-b3d5cc40587e
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = acf137c7-5af1-4bba-a3e4-b3d5cc40587e
DEBUG:root:SENDING MESSAGE id ccf2e85b-393e-4cac-bfc9-0086866ae184 with action generate_private_info to https://auth1:443/api/queues/orchestra_performer/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue orchestra_performer
DEBUG:root:The MESSAGE is LOCAL and with id ccf2e85b-393e-4cac-bfc9-0086866ae184
DEBUG:root:EXEC ACTION handler for MESSAGE id 96e773fd-ecee-40ac-8fbf-4fc5ba69fd0d (QUEUE internal.frestq)
DEBUG:root:UPDATING TASK with id c2033b86-4e5d-4568-a8b5-c748936f0e30
DEBUG:root:SETTING TASK FIELD 'output_data' to: ["\n<!-- ATTENTION! WE STRONGLY ADVICE AGAINST EDITING THIS FILE!\n \n This is a protocol information file. It contains all the \n parameters of a protocol session as agreed by all parties.\n \n Each party must hold an identical copy of this file. DO NOT \n UNDER ANY CIRCUMSTANCES EDIT THIS FILE after you and the \n administrators of the other parties have agreed on its content.\n If you do, then there are no security guarantees.\n \n If the Fiat-Shamir heuristic is used, then DO NOT EDIT THIS \n FILE UNDER ANY CIRCUMSTANCES! Any Fiat-Shamir proof of \n correctness computed before this file was changed will be \n rejected after the change. This can not be corrected without \n access to the original version of this file! -->\n\n<protocol>\n\n <!-- Protocol version for which this protocol info is intended. -->\n <version>0.1</version>\n\n <!-- Session identifier of this protocol execution. This must be \n globally unique for all executions of all protocols. -->\n <sid>0-b4ef654c-5709-480e-8907-0993b8c4fd77</sid>\n\n <!-- Name of this protocol execution. This is a short descriptive \n name. -->\n <name>5587</name>\n\n <!-- Description of this protocol execution. This is a longer \n description than the name. -->\n <descr></descr>\n\n <!-- Number of parties. -->\n <nopart>2</nopart>\n\n <!-- Number of parties needed to violate privacy. This must at \n least be majority. -->\n <thres>2</thres>\n\n <!-- Group over which the protocol is executed. An instance of \n vfork.arithm.PGroup. -->\n <pgroup>vfork.arithm.ModPGroup(safe-prime modulus=2*order+1. order bit-length = 2048)::0000000002010000001676666f726b2e61726974686d2e4d6f645047726f7570000000000401000001010188cb0fcd7f00ffd629ee7c0426036c09cd1ae4576e3cde79680733bd13b0b1ef6ace0082d1cc0839d8d8f89d302570dcd4b7178fd8edfd54166d891b5f5b435c0cba214c471dda545897a12a9b53956fb76a6d647295011bec650e0609b50f97ffa16201ffd5b6368083965abf0a2f73ae0c2a9dc315ca63253df511176551961440aebbee1495c5bf318b9228c77938c4508063048161e9e4d83cbec3a3c16d856d1cf4d5f5c10d979476b39cd3541786fbc22d12326d8c66119a847c360e36294d4e1d14b1f80757f9fbfec49146e86b60130ecda55ac889aa733198a849946656c37cb5cbe3fd60d92900476ee6a9dac4825d89296fb5601a357de2121537010000010100c46587e6bf807feb14f73e021301b604e68d722bb71e6f3cb40399de89d858f7b567004168e6041cec6c7c4e9812b86e6a5b8bc7ec76feaa0b36c48dafada1ae065d10a6238eed2a2c4bd0954da9cab7dbb536b2394a808df632870304da87cbffd0b100ffeadb1b4041cb2d5f8517b9d706154ee18ae531929efa888bb2a8cb0a20575df70a4ae2df98c5c91463bc9c622840318240b0f4f26c1e5f61d1e0b6c2b68e7a6afae086cbca3b59ce69aa0bc37de116891936c63308cd423e1b071b14a6a70e8a58fc03abfcfdff6248a37435b0098766d2ad6444d53998cc5424ca332b61be5ae5f1feb06c948023b77354ed62412ec494b7dab00d1abef1090a9b010000010100d7ebb637de2d1122a2a013e37fa08c2ed2aebfbfc3661bfcf852e836b9ed1bf67558183f00e2bc6b9ba1de3606249f614cdbc7bfaf8e9fd804f8bf126ec8a08f18a37647be03aeced8900202ec21411054aa0fed94f823eb92db8fb3a4e1ac3cf418df5cf71612e5f58252afa8dcc79c4c3a4804257618312555df143d932ef647562cf9751b42c8752e5a7d2e5e80327d626bb72bc375be8ab47e35b17130691e1279b7681145cdfe0c273f5be00c0abf8dfaa566935555b4c6f1dc3fefceafc9b805da9d014d1e6810b6d92f80220d9c8ce480d959e9f9264f7ea253222364a7a31d6a9bd661ed204dd813d6c1d22a77f4d683dc6d43ddd12bf732033a1ddb010000000400000001</pgroup>\n\n <!-- Number of ciphertexts shuffled in parallel. -->\n <width>1</width>\n\n <!-- Interface that defines how to communicate with the mix-net. \n Possible values are \"raw\", \"native\", \"helios\", and \"tvs\", or \n the name of a subclass of vfork.protocol.mixnet.\n MixNetElGamalInterface. See the user manual for more \n information on interfaces. -->\n <inter>native</inter>\n\n <!-- Maximal number of ciphertexts for which precomputation is \n performed. If this is set to zero, then it is assumed that \n precomputation is not performed as a separate phase, i.e., it \n defaults to the number of submitted ciphertexts during mixing. \n -->\n <maxciph>0</maxciph>\n\n <!-- Decides statistical error in distribution. -->\n <statdist>100</statdist>\n\n <!-- Bit length of challenges in interactive proofs. -->\n <cbitlen>100</cbitlen>\n\n <!-- Bit length of challenges in non-interactive random-oracle \n proofs. -->\n <cbitlenro>200</cbitlenro>\n\n <!-- Bit length of each component in random vectors used for \n batching. -->\n <vbitlen>100</vbitlen>\n\n <!-- Bit length of each component in random vectors used for \n batching in non-interactive random-oracle proofs. -->\n <vbitlenro>200</vbitlenro>\n\n <!-- Pseudo random generator used to derive random vectors from \n jointly generated seeds. This can be one of the strings \"SHA-\n 256\", \"SHA-384\", or \"SHA-512\", in which case vfork.crypto.\n PRGHeuristic is instantiated based on this hashfunction, or it \n can be an instance of vfork.crypto.PRG. -->\n <prg>SHA-256</prg>\n\n <!-- Hashfunction used to implement random oracles. It can be one \n of the strings \"SHA-256\", \"SHA-384\", or \"SHA-512\", in which \n case vfork.crypto.HashfunctionHeuristic is is instantiated, or \n an instance of vfork.crypto.Hashfunction. Random oracles with \n various output lengths are then implemented, using the given \n hashfunction, in vfork.crypto.RandomOracle.\n WARNING! Do not change the default unless you know exactly \n what you are doing. -->\n <rohash>SHA-256</rohash>\n\n <!-- Determines if the proofs of correctness of an execution are \n interactive or non-interactive (\"interactive\" or \n \"noninteractive\"). -->\n <corr>noninteractive</corr>\n\n <party>\n\n <!-- Sorting attribute used to sort parties with respect to their \n roles in the protocol. This is used to assign roles in \n protocols where different parties play different roles. -->\n <srtbyrole>anyrole</srtbyrole>\n\n <!-- Name of party. -->\n <name>Auth2</name>\n\n <!-- Description of party. -->\n <pdescr></pdescr>\n\n <!-- Public signature key (instance of crypto.SignaturePKey). -->\n <pkey>vfork.crypto.SignaturePKeyHeuristic(RSA, bitlength=2048)::0000000002010000002376666f726b2e63727970746f2e5369676e6174757265504b65794865757269737469630000000002010000000400000800010000012630820122300d06092a864886f70d01010105000382010f003082010a02820101008de325dceaba3fe44e3618499133e3972f1bd03381d7cc047da585e4e00a9ae753e65e1178221826a309dd679d167e56e20667ed8231a2808cd20b1f183a5c80b5c539c413e6bb18f5ab10956e32749c1f741b59ca7d9b0ac9bc01f0f7aeeeb710f6ad244a091bc60015b818fbfcbcbc7edf255b05bb27eb199fb2a704017a0c0dae6cf34dff7ea32ac198d38c3da2b8d8adec9a78250378832e6774c617453db61eb2e537af40461e352133551ccf964cead6a61ae27f4569ac1931c83e1716964d3951a11b5209c6cd87d56a1f68ce67f02a0d155bf877836de4384b2b344dbfbfdf639f6bea4b4c86f4c9c0b4bab9151476da19afdcaa29a77ca081c49e110203010001</pkey>\n\n <!-- URL to our HTTP server. -->\n <http>http://auth2:4081</http>\n\n <!-- Socket address given as <hostname>:<port> to our hint server. \n A hint server is a simple UDP server that reduces latency and \n traffic on the HTTP servers. -->\n <hint>127.0.0.1:8081</hint>\n\n </party>\n\n</protocol>\n\n"]
DEBUG:root:SETTING TASK FIELD 'status' to 'finished'
DEBUG:root:SENDING TASK 71f44130-a294-4370-a1b1-59c97cece8c4
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = 71f44130-a294-4370-a1b1-59c97cece8c4
DEBUG:root:SENDING MESSAGE id 0e483440-2b4f-4749-9bfe-357e93f893c6 with action merge_protinfo to https://auth1:443/api/queues/orchestra_director/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue orchestra_director
DEBUG:root:The MESSAGE is LOCAL and with id 0e483440-2b4f-4749-9bfe-357e93f893c6
INFO:root:adding job in sched for queue orchestra_director
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:16.364716)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_director/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 6/6] 172.17.42.1 () {44 vars in 2592 bytes} [Thu Jul 23 08:01:16 2015] POST /api/queues/orchestra_director/ => generated 0 bytes in 5 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 0)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:16.364716)
DEBUG:root:EXEC ACTION handler for MESSAGE id 0e483440-2b4f-4749-9bfe-357e93f893c6 (QUEUE orchestra_director)
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:root:EXEC TASK with id 71f44130-a294-4370-a1b1-59c97cece8c4
DEBUG:root:CREATE local SEQUENTIAL TASK with ID a925afcd-f4ea-445d-8c8a-eef43a317e7c
killing previous vfork instances..
DEBUG:root:CREATE local SYNCHRONIZED TASK with ID ce03a62c-3f21-420d-b840-bf5cb284dfd4
DEBUG:root:CREATE local TASK for action generate_public_key with ID c92f811f-b521-4580-be20-45488fffa07c
DEBUG:root:CREATE local TASK for action generate_public_key with ID 6f81d37c-e84a-4e00-a176-a7b6b435dfc7
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "send_synchronization_message (trigger: now, next run at: 2015-07-23 08:01:16.881135)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Removed job "send_synchronization_message (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:apscheduler.scheduler:Added job "send_synchronization_message (trigger: now, next run at: 2015-07-23 08:01:16.882018)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "send_synchronization_message (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:16.881135)
DEBUG:root:SENDING SYNC MESSAGE to SUBTASK with id c92f811f-b521-4580-be20-45488fffa07c
INFO:apscheduler.scheduler:Removed job "send_synchronization_message (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "send_synchronization_message (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:16.882018)
DEBUG:root:SENDING SYNC MESSAGE to SUBTASK with id 6f81d37c-e84a-4e00-a176-a7b6b435dfc7
DEBUG:root:SENDING MESSAGE id 6fb2e5f4-a69e-40e1-bc26-dc77dc148601 with action frestq.synchronize_task to https://auth2:443/api/queues/internal.frestq/
DEBUG:root:SENDING MESSAGE id 11ea0ebe-d471-47c8-ae62-8aa66c09ae8c with action frestq.synchronize_task to https://auth1:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id 11ea0ebe-d471-47c8-ae62-8aa66c09ae8c
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:16.950312)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
[pid: 149|app: 0|req: 7/7] 172.17.42.1 () {44 vars in 2588 bytes} [Thu Jul 23 08:01:16 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 6 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 3)
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:16.950312)
DEBUG:root:EXEC ACTION handler for MESSAGE id 11ea0ebe-d471-47c8-ae62-8aa66c09ae8c (QUEUE internal.frestq)
DEBUG:root:SYNCING TASK with id c92f811f-b521-4580-be20-45488fffa07c
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "send_synchronization_message (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Job "send_synchronization_message (trigger: now, next run at: None)" executed successfully
INFO:root:adding job in sched for queue vfork_queue
INFO:apscheduler.scheduler:Added job "reserve_task (trigger: now, next run at: 2015-07-23 08:01:17.008039)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Removed job "reserve_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "reserve_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:17.008039)
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id c572ad93-1282-4cf6-a552-6fd6286bcdb6
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:17.061910)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
[pid: 149|app: 0|req: 8/8] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:17 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 8 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 1)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
@
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:17.061910)
DEBUG:root:EXEC ACTION handler for MESSAGE id c572ad93-1282-4cf6-a552-6fd6286bcdb6 (QUEUE internal.frestq)
DEBUG:root:SENDING ACK RESERVATION TO SENDER of task with id c92f811f-b521-4580-be20-45488fffa07c
DEBUG:root:SENDING MESSAGE id c54362ed-0d8b-4993-8239-33470e7b668d with action frestq.confirm_task_reservation to https://auth1:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:CONFIRMED TASK RESERVATION with id 6f81d37c-e84a-4e00-a176-a7b6b435dfc7
INFO:apscheduler.scheduler:Added job "director_cancel_reserved_subtask (trigger: date[2015-07-23 08:02:17.055573], next run at: 2015-07-23 08:02:17.055573)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.935840 seconds)
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.146607)" to job store "default"
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id c54362ed-0d8b-4993-8239-33470e7b668d
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:17.150445)" to job store "default"
[pid: 149|app: 0|req: 9/9] 172.17.42.1 () {44 vars in 2586 bytes} [Thu Jul 23 08:01:17 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 3 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 2)
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:17.146607)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.904052 seconds)
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.893677 seconds)
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.155703)" to job store "default"
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:17.150445)
DEBUG:root:EXEC ACTION handler for MESSAGE id c54362ed-0d8b-4993-8239-33470e7b668d (QUEUE internal.frestq)
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.155703)" (scheduled at 2015-07-23 08:01:17.155703)
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.891824 seconds)
INFO:apscheduler.scheduler:Added job "cancel_reserved_subtask (trigger: date[2015-07-23 08:02:17.178295], next run at: 2015-07-23 08:02:17.178295)" to job store "default"
DEBUG:apscheduler.threadpool:Started worker thread
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.856509 seconds)
DEBUG:root:SENDING MESSAGE id 83f310c7-c1f2-465c-bc66-e55692ba9428 with action frestq.execute_synchronized to https://auth1:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:SENDING MESSAGE id 30e5a70a-3967-4136-8df9-ed78d57b39e3 with action frestq.execute_synchronized to https://auth2:443/api/queues/internal.frestq/
DEBUG:root:CONFIRMED TASK RESERVATION with id c92f811f-b521-4580-be20-45488fffa07c
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
INFO:apscheduler.scheduler:Added job "director_cancel_reserved_subtask (trigger: date[2015-07-23 08:02:17.088338], next run at: 2015-07-23 08:02:17.088338)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.787144 seconds)
DEBUG:root:The MESSAGE is LOCAL and with id 83f310c7-c1f2-465c-bc66-e55692ba9428
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:17.271588)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:17.271588)" (scheduled at 2015-07-23 08:01:17.271588)
DEBUG:root:EXEC ACTION handler for MESSAGE id 83f310c7-c1f2-465c-bc66-e55692ba9428 (QUEUE internal.frestq)
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 10/10] 172.17.42.1 () {44 vars in 2588 bytes} [Thu Jul 23 08:01:17 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 20 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 0)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.783340 seconds)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.783340 seconds)
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.272668)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.292832)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:17.272668)" (scheduled at 2015-07-23 08:01:17.272668)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:root:EXECUTING synchronized SUBTASK with id c92f811f-b521-4580-be20-45488fffa07c, action = generate_public_key
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 59.762262 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:17.292832)
DEBUG:root:SENDING MESSAGE id 858b8f20-3e9b-4c78-bac8-3a1068d6a611 with action frestq.execute_synchronized to https://auth2:443/api/queues/internal.frestq/
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
killing previous vfork instances..
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
call_cmd: calling vmn -keygen publicKey_raw
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
output =
-----------------------------------------------------------
This protocol is based on the Vfork software.
Copyright 2008 2009 2010 2011 2012 Douglas Wikstrom. See
<http://www.vfork.com>
Vfork is free software: you can redistribute it
and/or modify it under the terms of the GNU Lesser General
Public License as published by the Free Software
Foundation, either version 3 of the License, or (at your
option) any later version.
Vfork is distributed in the hope that it will be
useful, but WITHOUT ANY WARRANTY; without even the implied
warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR
PURPOSE. See the GNU Lesser General Public License for
more details.
You should have received a copy of the GNU Lesser General
Public License along with Vfork. If not, see
<http://www.gnu.org/licenses/>.
-----------------------------------------------------------
The arithmetic of Vfork is optionally mapped to
native calls to the GNU Multiple Precision Arithmetic
Library (GMP) generously made available under the LGPL
license. See <http://www.gmplib.org>.
-----------------------------------------------------------
-----------------------------------------------------------
Mix-server 1 running mixnet based on repeated
re-encryption and permutation followed by joint
decryption. Detailed information about all parameters
are found in the info files.
-----------------------------------------------------------
150723 08:01:17 Starting hint server.
150723 08:01:17 Starting http server.
150723 08:01:17 Starting hint server.
150723 08:01:17 Starting http server.
150723 08:01:17 Synchronizing with the other servers. Please wait.
150723 08:01:18 Generate and read plain keys.
150723 08:01:18 | Generate key-pair.
150723 08:01:18 | Exchange public keys with all parties.
150723 08:01:18 | | Publish public key.
150723 08:01:18 | | Read public key of Party2.
DEBUG:apscheduler.threadpool:Exiting worker thread
output = 150723 08:01:19 | | Parsed public key successfully.
150723 08:01:19 | Writing keys to file.
150723 08:01:19 Generate independent generator.
150723 08:01:19 | Execute Pedersen 2 times with rotating dealer.
150723 08:01:19 | | Deal a secret using Pedersen VSS.
150723 08:01:19 | | | Generate checking elements.
150723 08:01:19 | | | Compute encrypted shares for all parties.
150723 08:01:19 | | | Publish checking elements and encrypted shares.
150723 08:01:19 | | | Exchange verdicts.
150723 08:01:19 | | | | Publish verdict (true).
output = 150723 08:01:19 | | | | Read verdict of Party2.
150723 08:01:19 | | | | Parse verdict (true).
150723 08:01:19 | | | Sharing completed.
150723 08:01:19 | | Verify Pedersen VSS of Party2.
150723 08:01:19 | | | Read checking elements and ciphertexts from Party2.
150723 08:01:19 | | | Our share is correct.
150723 08:01:19 | | | Exchange verdicts.
150723 08:01:19 | | | | Publish verdict (true).
150723 08:01:19 | | | | Read verdict of Party2.
150723 08:01:19 | | | | Parse verdict (true).
150723 08:01:19 | | | Sharing of Party2 is accepted.
150723 08:01:19 | Write independent generator to file.
150723 08:01:19 Generate distributed keys for mix-servers.
150723 08:01:19 | Generate distributed keys.
150723 08:01:19 | | Generate secret key.
150723 08:01:19 | | | Write secret key to file.
150723 08:01:19 | | Verifiably secret share secret key.
150723 08:01:19 | | | Execute Pedersen 2 times with rotating dealer.
150723 08:01:19 | | | | Deal a secret using Pedersen VSS.
150723 08:01:19 | | | | | Generate checking elements.
150723 08:01:19 | | | | | Compute encrypted shares for all parties.
150723 08:01:20 | | | | | Publish checking elements and encrypted shares.
150723 08:01:20 | | | | | Exchange verdicts.
150723 08:01:20 | | | | | | Publish verdict (true).
150723 08:01:20 | | | | | | Read verdict of Party2.
150723 08:01:20 | | | | | | Parse verdict (true).
150723 08:01:20 | | | | | Write state to file.
150723 08:01:20 | | | | | Sharing completed.
150723 08:01:20 | | | | Verify Pedersen VSS of Party2.
150723 08:01:20 | | | | | Read checking elements and ciphertexts from Party2.
150723 08:01:20 | | | | | Our share is correct.
150723 08:01:20 | | | | | Exchange verdicts.
150723 08:01:20 | | | | | | Publish verdict (true).
150723 08:01:20 | | | | | | Read verdict of Party2.
output =
150723 08:01:20 | | | | | | Parse verdict (true).
150723 08:01:20 | | | | | Sharing of Party2 is accepted.
150723 08:01:20 | | | | | Write state to file.
150723 08:01:20 Joint key generation completed after 0h 0m 2s.
150723 08:01:20 Waiting for mutual shutdown acknowledgements.
150723 08:01:20 | Publish acknowledgement.
150723 08:01:20 | Wait for Party2 to acknowledge.
150723 08:01:20 Waiting for mutual shutdown acknowledgements.
150723 08:01:20 | Publish acknowledgement.
150723 08:01:20 | Wait for Party2 to acknowledge.
150723 08:01:20 Allow download of our acknowledgment for another 1 seconds.
output = 150723 08:01:21 Stopping hint server.
150723 08:01:21 Stopping http server.
call_cmd: calling vmnc -pkey -outi json publicKey_raw publicKey_json
INFO:apscheduler.scheduler:Job "reserve_task (trigger: now, next run at: None)" executed successfully
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id 22866bbf-098b-4181-a3de-3a22045c3eae
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:26.592249)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:26.592249)" to job store "default"
[pid: 149|app: 0|req: 11/11] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:26 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 6 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 3)
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 50.434557 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:26.592249)
DEBUG:root:EXEC ACTION handler for MESSAGE id 22866bbf-098b-4181-a3de-3a22045c3eae (QUEUE internal.frestq)
DEBUG:root:UPDATING TASK with id 6f81d37c-e84a-4e00-a176-a7b6b435dfc7
DEBUG:root:SETTING TASK FIELD 'output_data' to: null
DEBUG:root:SETTING TASK FIELD 'status' to 'finished'
DEBUG:root:SENDING TASK da5a16ef-063c-4a0a-9ae9-ea55dfde506c
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = da5a16ef-063c-4a0a-9ae9-ea55dfde506c
DEBUG:root:SENDING MESSAGE id 942c0801-09aa-4ad2-a75c-93fd68abf718 with action return_election to https://auth1:443/api/queues/orchestra_director/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue orchestra_director
DEBUG:root:The MESSAGE is LOCAL and with id 942c0801-09aa-4ad2-a75c-93fd68abf718
INFO:root:adding job in sched for queue orchestra_director
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:26.782563)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_director/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 12/12] 172.17.42.1 () {44 vars in 2592 bytes} [Thu Jul 23 08:01:26 2015] POST /api/queues/orchestra_director/ => generated 0 bytes in 7 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 1)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:26.782563)
DEBUG:root:EXEC ACTION handler for MESSAGE id 942c0801-09aa-4ad2-a75c-93fd68abf718 (QUEUE orchestra_director)
DEBUG:root:EXEC TASK with id da5a16ef-063c-4a0a-9ae9-ea55dfde506c
callback_url, http://auth1:8000/key_done
{"status": "finished", "reference": {"action": "POST /election", "election_id": 5587}, "session_data": [{"pubkey": {"q": "24792774508736884642868649594982829646677044143456685966902090450389126928108831401260556520412635107010557472033959413182721740344201744439332485685961403243832055703485006331622597516714353334475003356107214415133930521931501335636267863542365051534250347372371067531454567272385185891163945756520887249904654258635354225185183883072436706698802915430665330310171817147030511296815138402638418197652072758525915640803066679883309656829521003317945389314422254112846989412579196000319352105328237736727287933765675623872956765501985588170384171812463052893055840132089533980513123557770728491280124996262883108653723", "p": "49585549017473769285737299189965659293354088286913371933804180900778253856217662802521113040825270214021114944067918826365443480688403488878664971371922806487664111406970012663245195033428706668950006712214428830267861043863002671272535727084730103068500694744742135062909134544770371782327891513041774499809308517270708450370367766144873413397605830861330660620343634294061022593630276805276836395304145517051831281606133359766619313659042006635890778628844508225693978825158392000638704210656475473454575867531351247745913531003971176340768343624926105786111680264179067961026247115541456982560249992525766217307447", "y": "32611901098307318730078719376364251355800218177720512787181709182709424083168091207110499375096494522267179214644105178122572475724721845896896982715568622958247206834880783161955321360265365723712265415689712037918634425272269420848328583541945207935252635333019836681062757895650881963120242133260062658939781338422308887290828208506187868730989634273443638775566880999618178686434390192803105642840205232229370335672761343181929829367289575285279735053490755967869215019264985898062876106345438676856996906299536887248565179664737646542351691357710552838925044022469958139918905988598105370812677868266652343353374", "g": "27257469383433468307851821232336029008797963446516266868278476598991619799718416119050669032044861635977216445034054414149795443466616532657735624478207460577590891079795564114912418442396707864995938563067755479563850474870766067031326511471051504594777928264027177308453446787478587442663554203039337902473879502917292403539820877956251471612701203572143972352943753791062696757791667318486190154610777475721752749567975013100844032853600120195534259802017090281900264646220781224136443700521419393245058421718455034330177739612895494553069450438317893406027741045575821283411891535713793639123109933196544017309147"}, "session_id": "0-b4ef654c-5709-480e-8907-0993b8c4fd77"}]}
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): auth1
DEBUG:requests.packages.urllib3.connectionpool:"POST /key_done HTTP/1.1" 200 None
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:root:CREATE local TASK for action tally_election with ID df67ad10-3de1-49ac-97f6-4af2d9dec68f
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = df67ad10-3de1-49ac-97f6-4af2d9dec68f
DEBUG:root:SENDING MESSAGE id a7ba4159-309d-4dfe-82b3-afd0feeef18a with action tally_election to https://auth1:443/api/queues/launch_task/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:root:RECEIVED MESSAGE in queue launch_task
DEBUG:root:The MESSAGE is LOCAL and with id a7ba4159-309d-4dfe-82b3-afd0feeef18a
INFO:root:adding job in sched for queue launch_task
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:28.127290)" to job store "default"
INFO:root:adding job in sched for queue launch_task
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:28.127290)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/launch_task/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 14/13] 172.17.42.1 () {44 vars in 2578 bytes} [Thu Jul 23 08:01:28 2015] POST /api/queues/launch_task/ => generated 0 bytes in 5 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 0)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:28.127290)
DEBUG:root:EXEC ACTION handler for MESSAGE id a7ba4159-309d-4dfe-82b3-afd0feeef18a (QUEUE launch_task)
DEBUG:root:EXEC TASK with id df67ad10-3de1-49ac-97f6-4af2d9dec68f
[pid: 149|app: 0|req: 14/14] 172.17.42.1 () {44 vars in 2564 bytes} [Thu Jul 23 08:01:28 2015] POST /public_api/tally => generated 15 bytes in 62 msecs (HTTP/1.1 202) 2 headers in 85 bytes (2 switches on core 2)
DEBUG:root:CREATE local PARALLEL TASK with ID 5bdea4c3-89ba-4401-bc14-ae6ace4385d9
DEBUG:root:CREATE local TASK for action review_tally with ID 05b4f843-6120-4218-b647-2b89055c3793
DEBUG:root:CREATE local TASK for action review_tally with ID 8584550f-9d6b-43bf-bfcd-9245df94583f
DEBUG:root:CREATE local SEQUENTIAL TASK with ID 375ebf6d-51f1-4bcf-a2b6-eff6227a9bff
DEBUG:root:CREATE local SYNCHRONIZED TASK with ID 39f2167c-4926-493a-a54a-d60b26775082
DEBUG:root:CREATE local TASK for action perform_tally with ID b8b5d393-b21a-4670-85fa-9da9a063ae51
DEBUG:root:CREATE local TASK for action perform_tally with ID 3f313636-f288-4b50-87b9-c85f2230fcaa
DEBUG:root:CREATE local PARALLEL TASK with ID f08ef234-fb2c-4573-a1d9-ee33208e2f3b
DEBUG:root:CREATE local TASK for action verify_and_publish_tally with ID 8615b65c-f88d-4702-a8a6-dd2dcb8df76e
DEBUG:root:CREATE local TASK for action verify_and_publish_tally with ID 1f87e5fe-ebce-4e38-be35-fb6e83b90355
DEBUG:root:CREATE local TASK for action return_tally with ID 6247cd94-5321-4040-a20f-6eeab10da9fa
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Added job "execute_task (trigger: now, next run at: 2015-07-23 08:01:28.296432)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Removed job "execute_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:apscheduler.scheduler:Added job "execute_task (trigger: now, next run at: 2015-07-23 08:01:28.297089)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "execute_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:28.296432)
INFO:apscheduler.scheduler:Removed job "execute_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "execute_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:28.297089)
DEBUG:root:SENDING TASK 05b4f843-6120-4218-b647-2b89055c3793
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = 05b4f843-6120-4218-b647-2b89055c3793
DEBUG:root:SENDING TASK 8584550f-9d6b-43bf-bfcd-9245df94583f
DEBUG:root:SEND task MESSAGE to https://auth2:443/api/queues, TASK id = 8584550f-9d6b-43bf-bfcd-9245df94583f
DEBUG:root:SENDING MESSAGE id 33e71002-a1a0-45fb-b277-7d55efc1a3c8 with action review_tally to https://auth1:443/api/queues/orchestra_performer/
DEBUG:root:SENDING MESSAGE id 9ad1a29b-df8f-4bf2-94b4-c66c31048ff4 with action review_tally to https://auth2:443/api/queues/orchestra_performer/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
DEBUG:root:RECEIVED MESSAGE in queue orchestra_performer
DEBUG:root:The MESSAGE is LOCAL and with id 33e71002-a1a0-45fb-b277-7d55efc1a3c8
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:28.361854)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
[pid: 149|app: 0|req: 15/15] 172.17.42.1 () {44 vars in 2594 bytes} [Thu Jul 23 08:01:28 2015] POST /api/queues/orchestra_performer/ => generated 0 bytes in 5 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 3)
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_performer/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:28.361854)
DEBUG:root:EXEC ACTION handler for MESSAGE id 33e71002-a1a0-45fb-b277-7d55efc1a3c8 (QUEUE orchestra_performer)
DEBUG:root:EXEC TASK with id 05b4f843-6120-4218-b647-2b89055c3793
INFO:apscheduler.scheduler:Job "execute_task (trigger: now, next run at: None)" executed successfully
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_performer/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "execute_task (trigger: now, next run at: None)" executed successfully
killing previous vfork instances..
INFO:requests.packages.urllib3.connectionpool:Starting new HTTP connection (1): auth1
DEBUG:requests.packages.urllib3.connectionpool:"GET /ctexts5587 HTTP/1.1" 200 139252
------ Reading and verifying POK of plaintext for the votes..
------ Reading and verifying POK of plaintext for the votes..
------ Verified 100 votes in total (0 invalid)
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id bf4a296e-c421-4748-bb5f-08a1d975b945
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:29.632113)" to job store "default"
[pid: 149|app: 0|req: 16/16] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:29 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 5 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 1)
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 47.409033 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:29.632113)
DEBUG:root:EXEC ACTION handler for MESSAGE id bf4a296e-c421-4748-bb5f-08a1d975b945 (QUEUE internal.frestq)
DEBUG:root:UPDATING TASK with id 8584550f-9d6b-43bf-bfcd-9245df94583f
DEBUG:root:SETTING TASK FIELD 'output_data' to: null
DEBUG:root:SETTING TASK FIELD 'status' to 'finished'
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "send_synchronization_message (trigger: now, next run at: 2015-07-23 08:01:29.757393)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "send_synchronization_message (trigger: now, next run at: 2015-07-23 08:01:29.757734)" to job store "default"
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "send_synchronization_message (trigger: now, next run at: None)"
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "send_synchronization_message (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:29.757393)
DEBUG:root:SENDING SYNC MESSAGE to SUBTASK with id b8b5d393-b21a-4670-85fa-9da9a063ae51
INFO:apscheduler.scheduler:Running job "send_synchronization_message (trigger: now, next run at: 2015-07-23 08:01:29.757734)" (scheduled at 2015-07-23 08:01:29.757734)
DEBUG:root:SENDING SYNC MESSAGE to SUBTASK with id 3f313636-f288-4b50-87b9-c85f2230fcaa
DEBUG:root:SENDING MESSAGE id 0912e0ad-a60a-45f3-9a79-32abd4db89d0 with action frestq.synchronize_task to https://auth2:443/api/queues/internal.frestq/
DEBUG:root:SENDING MESSAGE id 99c6bb2e-98c2-45e5-991b-1cdaa0e0c1bf with action frestq.synchronize_task to https://auth1:443/api/queues/internal.frestq/
INFO:apscheduler.scheduler:Removed job "send_synchronization_message (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 47.282712 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id 99c6bb2e-98c2-45e5-991b-1cdaa0e0c1bf
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:29.852826)" to job store "default"
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 17/17] 172.17.42.1 () {44 vars in 2586 bytes} [Thu Jul 23 08:01:29 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 4 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 0)
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "send_synchronization_message (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Job "send_synchronization_message (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 47.178899 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:29.852826)
DEBUG:root:EXEC ACTION handler for MESSAGE id 99c6bb2e-98c2-45e5-991b-1cdaa0e0c1bf (QUEUE internal.frestq)
DEBUG:root:SYNCING TASK with id b8b5d393-b21a-4670-85fa-9da9a063ae51
INFO:root:adding job in sched for queue vfork_queue
INFO:apscheduler.scheduler:Added job "reserve_task (trigger: now, next run at: 2015-07-23 08:01:29.911838)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Removed job "reserve_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "reserve_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:29.911838)
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id 82560048-a6d3-4a6c-a154-3b4f72c009a4
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:29.942998)" to job store "default"
[pid: 149|app: 0|req: 18/18] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:29 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 10 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 2)
DEBUG:root:SENDING ACK RESERVATION TO SENDER of task with id b8b5d393-b21a-4670-85fa-9da9a063ae51
DEBUG:root:SENDING MESSAGE id 593fb5e0-9adb-4042-add6-9ac4eccee45b with action frestq.confirm_task_reservation to https://auth1:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 47.099536 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:29.942998)
DEBUG:root:EXEC ACTION handler for MESSAGE id 82560048-a6d3-4a6c-a154-3b4f72c009a4 (QUEUE internal.frestq)
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id 593fb5e0-9adb-4042-add6-9ac4eccee45b
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:30.016302)" to job store "default"
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 19/19] 172.17.42.1 () {44 vars in 2586 bytes} [Thu Jul 23 08:01:30 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 6 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 3)
INFO:apscheduler.scheduler:Added job "cancel_reserved_subtask (trigger: date[2015-07-23 08:02:30.023809], next run at: 2015-07-23 08:02:30.023809)" to job store "default"
DEBUG:root:CONFIRMED TASK RESERVATION with id 3f313636-f288-4b50-87b9-c85f2230fcaa
INFO:apscheduler.scheduler:Added job "director_cancel_reserved_subtask (trigger: date[2015-07-23 08:02:29.938167], next run at: 2015-07-23 08:02:29.938167)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:30.016302)" (scheduled at 2015-07-23 08:01:30.016302)
DEBUG:root:EXEC ACTION handler for MESSAGE id 593fb5e0-9adb-4042-add6-9ac4eccee45b (QUEUE internal.frestq)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 47.022846 seconds)
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.075485)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.075766)" to job store "default"
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:root:CONFIRMED TASK RESERVATION with id b8b5d393-b21a-4670-85fa-9da9a063ae51
INFO:apscheduler.scheduler:Added job "director_cancel_reserved_subtask (trigger: date[2015-07-23 08:02:29.951513], next run at: 2015-07-23 08:02:29.951513)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:30.075485)
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.075766)" (scheduled at 2015-07-23 08:01:30.075766)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 46.969180 seconds)
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.148792)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.149074)" to job store "default"
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "director_synchronized_subtask_start (trigger: now, next run at: 2015-07-23 08:01:30.149074)" to job store "default"
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:root:SENDING MESSAGE id e425c082-18a0-496c-9b2a-5b86f71fd272 with action frestq.execute_synchronized to https://auth2:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
DEBUG:root:SENDING MESSAGE id cda8e7bf-6dad-46f1-a985-90efe10f6b3d with action frestq.execute_synchronized to https://auth1:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:30.148792)
INFO:apscheduler.scheduler:Removed job "director_synchronized_subtask_start (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 46.892524 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "director_synchronized_subtask_start (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:30.149074)
DEBUG:root:SENDING MESSAGE id 979d8586-cc36-403f-81f2-0d2c56085618 with action frestq.execute_synchronized to https://auth1:443/api/queues/internal.frestq/
DEBUG:root:SENDING MESSAGE id 1d1c96e5-cdb4-43f9-ae2f-d1f371d2f9a6 with action frestq.execute_synchronized to https://auth2:443/api/queues/internal.frestq/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id cda8e7bf-6dad-46f1-a985-90efe10f6b3d
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:30.262536)" to job store "default"
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 20/20] 172.17.42.1 () {44 vars in 2586 bytes} [Thu Jul 23 08:01:30 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 5 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 1)
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is LOCAL and with id 979d8586-cc36-403f-81f2-0d2c56085618
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 46.770335 seconds)
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:30.289348)" to job store "default"
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
DEBUG:apscheduler.scheduler:Looking for jobs to run
[pid: 149|app: 0|req: 21/21] 172.17.42.1 () {44 vars in 2586 bytes} [Thu Jul 23 08:01:30 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 29 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 0)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:30.262536)
DEBUG:root:EXEC ACTION handler for MESSAGE id cda8e7bf-6dad-46f1-a985-90efe10f6b3d (QUEUE internal.frestq)
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/internal.frestq/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 46.744331 seconds)
INFO:apscheduler.scheduler:Job "director_synchronized_subtask_start (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:30.289348)
DEBUG:root:EXEC ACTION handler for MESSAGE id 979d8586-cc36-403f-81f2-0d2c56085618 (QUEUE internal.frestq)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:root:EXECUTING synchronized SUBTASK with id b8b5d393-b21a-4670-85fa-9da9a063ae51, action = perform_tally
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
killing previous vfork instances..
call_cmd: calling vmn -mix privInfo.xml protInfo.xml ciphertexts_raw plaintexts_raw
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
output = -----------------------------------------------------------
Mix-server 1 running mixnet based on repeated
re-encryption and permutation followed by joint
decryption. Detailed information about all parameters
are found in the info files.
-----------------------------------------------------------
150723 08:01:30 Starting hint server.
150723 08:01:30 Starting http server.
150723 08:01:30 Synchronizing with the other servers. Please wait.
150723 08:01:31 Generate and read plain keys.
150723 08:01:31 | Read keys from file.
output = 150723 08:01:31 Generate independent generator.
150723 08:01:31 | Read independent generator from file.
150723 08:01:31 Generate distributed keys for mix-servers.
150723 08:01:31 | Generate distributed keys.
150723 08:01:31 | | Generate secret key.
150723 08:01:31 | | | Read secret key from file.
150723 08:01:31 | | Verifiably secret share secret key.
150723 08:01:31 | | | Execute Pedersen 2 times with rotating dealer.
150723 08:01:31 | | | | Deal a secret using Pedersen VSS.
150723 08:01:31 | | | | | Read state from file.
150723 08:01:31 | | | | Verify Pedersen VSS of Party2.
150723 08:01:31 | | | | | Read state from file.
150723 08:01:31 Importing ElGamal ciphertexts.
150723 08:01:32 Perform pre-computation for 100 senders.
150723 08:01:32 | Derive independent generators using RO.
150723 08:01:32 | Precompute permutation commitment.
150723 08:01:32 | | Generate random permutation.
150723 08:01:32 | | Write permutation to file.
150723 08:01:32 | | Generate commitment exponents.
150723 08:01:32 | | Write commitment exponents to file.
150723 08:01:32 | | Compute identity commitment.
150723 08:01:32 | | Write identity commitment to file.
150723 08:01:32 | Generate permutation commitment of Party1
150723 08:01:32 | | Publish permutation commitment.
150723 08:01:32 | | Prove correctness of permutation commitment.
150723 08:01:32 | | | Generate batching vector.
150723 08:01:32 | | | | Derive 256 bits using random oracle.
150723 08:01:32 | | | Compute commitment.
output = 150723 08:01:33 | | | Publish our commitment.
150723 08:01:33 | | | Generate challenge.
150723 08:01:33 | | | | Derive 200 bits using random oracle.
150723 08:01:33 | | | Compute reply.
150723 08:01:33 | | | Publish reply.
150723 08:01:33 | Generate permutation commitment of Party2
150723 08:01:33 | | Read permutation commitment of Party2.
output = 150723 08:01:34 | | Verify correctness of permutation commitment of Party2.
150723 08:01:34 | | | Generate batching vector.
150723 08:01:34 | | | | Derive 256 bits using random oracle.
150723 08:01:34 | | | Read the commitment.
output = 150723 08:01:34 | | | Generate challenge.
150723 08:01:34 | | | | Derive 200 bits using random oracle.
150723 08:01:34 | | | Read the reply.
150723 08:01:34 | | | Perform verification.
150723 08:01:35 | | | Accepted proof.
150723 08:01:35 | | Write permutation commitment to file.
150723 08:01:35 | Generate reencryption exponents.
150723 08:01:35 | Write reencryption exponents to file.
150723 08:01:35 | Compute reencryption factors.
output = 150723 08:01:35 | Write reencryption factors to file.
150723 08:01:35 Shrink precomputed values to 100 ciphertexts.
150723 08:01:35 | Shrink number of generators.
150723 08:01:35 | Shrink reencryption exponents.
150723 08:01:35 | Shrink reencryption factors.
150723 08:01:35 | Shrink permutation commitment of Party1
150723 08:01:35 | | Shrink commitment exponents.
150723 08:01:35 | | Shrink permutation.
150723 08:01:35 | | Shrink commitment exponents.
150723 08:01:35 | | Shrink permutation.
150723 08:01:35 | | Shrink permutation commitment.
150723 08:01:35 | Shrink permutation commitment of Party2
150723 08:01:35 | | Shrink permutation commitment.
150723 08:01:35 Mix 100 ciphertexts.
150723 08:01:35 | Publish mixed list.
150723 08:01:35 | Prove correctness of shuffle.
150723 08:01:35 | | Generate batching vector.
150723 08:01:35 | | | Derive 256 bits using random oracle.
150723 08:01:35 | | Compute commitment.
150723 08:01:36 | | Publish our commitment.
150723 08:01:36 | | Generate challenge.
150723 08:01:36 | | | Derive 200 bits using random oracle.
150723 08:01:36 | | Compute reply.
150723 08:01:36 | | Publish reply.
150723 08:01:36 | Read output from Party2.
output = 150723 08:01:36 | Verify correctness of shuffle of Party2.
150723 08:01:36 | | Generate batching vector.
150723 08:01:36 | | | Derive 256 bits using random oracle.
150723 08:01:36 | | Read the commitment.
150723 08:01:36 | | Generate challenge.
150723 08:01:36 | | | Derive 200 bits using random oracle.
150723 08:01:36 | | Read the reply.
150723 08:01:36 | | Perform verification.
150723 08:01:36 | | Accepted proof.
150723 08:01:36 Jointly decrypt ciphertexts.
150723 08:01:36 | Compute decryption factors.
output = 150723 08:01:37 | Publish decryption factors.
150723 08:01:37 | Execute prover of sigma proof.
150723 08:01:37 | | Generate seed for batching.
150723 08:01:37 | | | Derive 256 bits using random oracle.
150723 08:01:37 | | Compute our commitment.
150723 08:01:37 | | Publish our commitent.
150723 08:01:37 | | Generate challenge.
150723 08:01:37 | | | Derive 200 bits using random oracle.
150723 08:01:37 | | Compute reply.
150723 08:01:37 | | Publish reply.
150723 08:01:37 | Read decryption factors of Party2.
150723 08:01:37 | Verify the proof of Party2.
150723 08:01:37 | | Generate seed for batching.
150723 08:01:37 | | | Derive 256 bits using random oracle.
150723 08:01:37 | | Read the commitment.
150723 08:01:37 | | Generate challenge.
150723 08:01:37 | | | Derive 200 bits using random oracle.
150723 08:01:37 | | Read the reply.
150723 08:01:37 | | Perform verification.
150723 08:01:37 | | Accepted proof.
150723 08:01:38 Mixing phase completed after 0h 0m 7s.
150723 08:01:38 Waiting for mutual shutdown acknowledgements.
150723 08:01:38 | Publish acknowledgement.
150723 08:01:38 | Wait for Party2 to acknowledge.
150723 08:01:38 Waiting for mutual shutdown acknowledgements.
150723 08:01:38 | Publish acknowledgement.
150723 08:01:38 | Wait for Party2 to acknowledge.
150723 08:01:38 Allow download of our acknowledgment for another 1 seconds.
output = 150723 08:01:39 Stopping hint server.
150723 08:01:39 Stopping http server.
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id 66ba2db2-ccd4-4a19-bcb0-e240ade0dc49
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:41.378943)" to job store "default"
[pid: 149|app: 0|req: 22/22] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:41 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 9 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 2)
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 35.653151 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:41.378943)
DEBUG:root:EXEC ACTION handler for MESSAGE id 66ba2db2-ccd4-4a19-bcb0-e240ade0dc49 (QUEUE internal.frestq)
DEBUG:root:UPDATING TASK with id 3f313636-f288-4b50-87b9-c85f2230fcaa
DEBUG:root:SETTING TASK FIELD 'output_data' to: null
DEBUG:root:UPDATING TASK with id 3f313636-f288-4b50-87b9-c85f2230fcaa
DEBUG:root:SETTING TASK FIELD 'output_data' to: null
DEBUG:root:SETTING TASK FIELD 'status' to 'finished'
INFO:apscheduler.scheduler:Job "reserve_task (trigger: now, next run at: None)" executed successfully
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Added job "execute_task (trigger: now, next run at: 2015-07-23 08:01:41.592573)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Removed job "execute_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
INFO:apscheduler.scheduler:Added job "execute_task (trigger: now, next run at: 2015-07-23 08:01:41.593518)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "execute_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:41.592573)
INFO:apscheduler.scheduler:Removed job "execute_task (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "execute_task (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:41.593518)
DEBUG:root:SENDING TASK 1f87e5fe-ebce-4e38-be35-fb6e83b90355
DEBUG:root:SEND task MESSAGE to https://auth2:443/api/queues, TASK id = 1f87e5fe-ebce-4e38-be35-fb6e83b90355
DEBUG:root:SENDING TASK 8615b65c-f88d-4702-a8a6-dd2dcb8df76e
DEBUG:root:SEND task MESSAGE to https://auth1:443/api/queues, TASK id = 8615b65c-f88d-4702-a8a6-dd2dcb8df76e
DEBUG:root:SENDING MESSAGE id bc7838c2-4c03-4b4e-8210-32621db998b0 with action verify_and_publish_tally to https://auth2:443/api/queues/orchestra_performer/
DEBUG:root:SENDING MESSAGE id 0e2c8263-d8a9-4ade-8c24-5c9d1149013e with action verify_and_publish_tally to https://auth1:443/api/queues/orchestra_performer/
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth1
INFO:requests.packages.urllib3.connectionpool:Starting new HTTPS connection (1): auth2
DEBUG:root:RECEIVED MESSAGE in queue orchestra_performer
DEBUG:root:The MESSAGE is LOCAL and with id 0e2c8263-d8a9-4ade-8c24-5c9d1149013e
INFO:root:adding job in sched for queue orchestra_performer
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:41.675884)" to job store "default"
DEBUG:apscheduler.scheduler:Looking for jobs to run
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_performer/ HTTP/1.1" 200 0
[pid: 149|app: 0|req: 23/23] 172.17.42.1 () {44 vars in 2594 bytes} [Thu Jul 23 08:01:41 2015] POST /api/queues/orchestra_performer/ => generated 0 bytes in 7 msecs (HTTP/1.1 200) 2 headers in 78 bytes (1 switches on core 3)
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:No jobs; waiting until a job is added
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:41.675884)
DEBUG:root:EXEC ACTION handler for MESSAGE id 0e2c8263-d8a9-4ade-8c24-5c9d1149013e (QUEUE orchestra_performer)
DEBUG:root:EXEC TASK with id 8615b65c-f88d-4702-a8a6-dd2dcb8df76e
DEBUG:requests.packages.urllib3.connectionpool:"POST /api/queues/orchestra_performer/ HTTP/1.1" 200 0
INFO:apscheduler.scheduler:Job "execute_task (trigger: now, next run at: None)" executed successfully
INFO:apscheduler.scheduler:Job "execute_task (trigger: now, next run at: None)" executed successfully
call_cmd: calling vmnc -plain -outi json plaintexts_raw plaintexts_json
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:apscheduler.threadpool:Exiting worker thread
DEBUG:root:RECEIVED MESSAGE in queue internal.frestq
DEBUG:root:The MESSAGE is NOT LOCAL and with id e1f6fc33-bbda-4cf7-90f7-cb429aa80846
INFO:root:adding job in sched for queue internal.frestq
INFO:apscheduler.scheduler:Added job "call_action_handler (trigger: now, next run at: 2015-07-23 08:01:46.417360)" to job store "default"
[pid: 149|app: 0|req: 24/24] 172.28.128.37 () {44 vars in 2590 bytes} [Thu Jul 23 08:01:46 2015] POST /api/queues/internal.frestq/ => generated 0 bytes in 17 msecs (HTTP/1.1 200) 2 headers in 78 bytes (2 switches on core 1)
INFO:apscheduler.scheduler:Job "call_action_handler (trigger: now, next run at: None)" executed successfully
DEBUG:apscheduler.scheduler:Looking for jobs to run
INFO:apscheduler.scheduler:Removed job "call_action_handler (trigger: now, next run at: None)"
DEBUG:apscheduler.scheduler:Next wakeup is due at 2015-07-23 08:02:17.055573 (in 30.587962 seconds)
DEBUG:apscheduler.threadpool:Started worker thread
INFO:apscheduler.scheduler:Running job "call_action_handler (trigger: now, next run at: None)" (scheduled at 2015-07-23 08:01:46.417360)
DEBUG:root:EXEC ACTION handler for MESSAGE id e1f6fc33-bbda-4cf7-90f7-cb429aa80846 (QUEUE internal.frestq)
DEBUG:root:UPDATING TASK with id 1f87e5fe-ebce-4e38-be35-fb6e83b90355
DEBUG:root:SETTING TASK FIELD 'output_data' to: null
DEBUG:root:SETTING TASK FIELD 'status' to 'finished'
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment