golem_messages.exceptions.SignatureAlreadyExists

[ederenn]

Encountered on:

'GOLEM Version: 0.16.1+dev163.g4d164a7' 'Protocol Version: 28-testnet' 'golem_messages Version: 2.10.0'

during computations of a task in logs and in console window:

2018-07-03 18:41:52 ERROR    golem.network.concent.client        b'send_to_concent({'key': '9f3f2090-7ed5-11e8-8cb2-fc4f24641c30/ForceGetTaskResult', 'msg': ForceGetTaskResult(header=MessageHeader(type_=4009, timestamp=1530636112, encrypted=True), sig=b"\x88U\x80\x18O\xdd\xd5<\xd8\xcc\xb9#\x81\xe2\xa2|Io\xaabT\x18L4\x8e\x04\xf1\xc2n_E+0k\x03\xae\xa5\xbfO\x89\x9cVj\x13\xf4',\xd5\xdc?\x89H\xa1b)\xd7=\xa1;\xa3Q\x8b\xc4h\x00", slots=[['report_computed_task', ReportComputedTask(header=MessageHeader(type_=2004, timestamp=1530631680, encrypted=False), sig=b'\r\xbdVk\xeaA|2\x04G~\x174\xa3M\xb2\xda\x07\xac\x0c\xea\xa7\xf08WI;\x0f\xb6\xaf\x15\xedM\xb5\xecC\x00\xff\xc5\x8f\x82\x8c\xd5\xe6\xc5\xe5\xc7\xf6\x03\xfcmT\xa3\r\xdc1f\\\x94y\xa90\x9e0\x01', slots=[['result_type', 1], ['node_name', ''], ['address', '172.31.45.146'], ['node_info', {'hyperdrive_prv_port': 3282, 'hyperdrive_pub_port': 3282, 'key': 'fa499cec19cb0df0c973068c351cbac8e9f53265a42d4bfdf658798830ccc229b3dd8113dbc467a6377171c01ba40528320f397fd14fc59354d5dacbf86337c7', 'nat_type': 'Restric NAT', 'node_name': '', 'p2p_prv_port': 40106, 'p2p_pub_port': 40106, 'port_statuses': {}, 'prv_addr': '172.31.45.146', 'prv_addresses': ['172.31.45.146', '172.17.0.1'], 'prv_port': 40107, 'pub_addr': '35.180.43.86', 'pub_port': 40107}], ['port', 40107], ['key_id', 'fa499cec19cb0df0c973068c351cbac8e9f53265a42d4bfdf658798830ccc229b3dd8113dbc467a6377171c01ba40528320f397fd14fc59354d5dacbf86337c7'], ['extra_data', ['scene-Heli20_5_200020.png', 'stderr.log', 'stdout.log']], ['eth_account', '0xCf1b42595F3DDFA028ee6155DcCf2BF52d45842e'], ['task_to_compute', TaskToCompute(header=MessageHeader(type_=2002, timestamp=1530631663, encrypted=False), sig=b'\xd9\xe7I$\xd5)\x00\xd7z\x9b\xad\x04\xbe5\x05\xe8EapB\x01\x1eW\x9a\xe3\x0e\x85p\xf8rgw;\x1e\x9d\xad\xf2\x87\x0b\xec\xfdw\xf2\xb3D\xe8\x82\xfc\x90\x8f\\\xccj\x03{\xb3\x0bS\x05o\xfdXQ\xea\x00', slots=[['requestor_id', 'fc4f24641c30d708c66e2e2dc7f2cc42d3409844326cd794efa8e44b808d3334dd228abb5aaf647d86216f0ec517f41215f89cec4637fe743077bf359ec65958'], ['requestor_public_key', 'fc4f24641c30d708c66e2e2dc7f2cc42d3409844326cd794efa8e44b808d3334dd228abb5aaf647d86216f0ec517f41215f89cec4637fe743077bf359ec65958'], ['requestor_ethereum_public_key', 'fc4f24641c30d708c66e2e2dc7f2cc42d3409844326cd794efa8e44b808d3334dd228abb5aaf647d86216f0ec517f41215f89cec4637fe743077bf359ec65958'], ['provider_id', 'fa499cec19cb0df0c973068c351cbac8e9f53265a42d4bfdf658798830ccc229b3dd8113dbc467a6377171c01ba40528320f397fd14fc59354d5dacbf86337c7'], ['provider_public_key', 'fa499cec19cb0df0c973068c351cbac8e9f53265a42d4bfdf658798830ccc229b3dd8113dbc467a6377171c01ba40528320f397fd14fc59354d5dacbf86337c7'], ['provider_ethereum_public_key', 'fa499cec19cb0df0c973068c351cbac8e9f53265a42d4bfdf658798830ccc229b3dd8113dbc467a6377171c01ba40528320f397fd14fc59354d5dacbf86337c7'], ['compute_task_def', {'deadline': 1530632563.216921, 'docker_images': [{'image_id': None, 'repository': 'golemfactory/blender', 'tag': '1.4'}], 'extra_data': {'end_task': 20, 'frames': [20], 'outfilebasename': 'scene-Heli20_5', 'output_format': 'PNG', 'path_root': 'C:\\Users\\ederenn\\Desktop\\do scenariuszy', 'scene_file': '/golem/resources/scene-Helicopter-27-cycles.blend', 'script_src': '# This template is rendered by\n# apps.blender.resources.scenefileeditor.generate_blender_crop_file(),\n# written to tempfile and passed as arg to blender.\nimport bpy\n\nclass EngineWarning(bpy.types.Operator):\n    bl_idname = "wm.engine_warning"\n    bl_label = "Inform about not supported rendering engine"\n\n    def execute(self, context):\n        self.report({"ERROR"}, "Engine " + bpy.context.scene.render.engine + \\\n                               " not supported by Golem")\n        return {"FINISHED"}\n\nclass ShowInformation(bpy.types.Operator):\n    bl_idname = "wm.scene_information"\n    bl_label = "Inform user about scene settings"\n\n\n    def execute(self, context):\n        self.report({"INFO"}, "Engine: " +\n                              str(bpy.context.scene.render.engine))\n        if bpy.context.scene.render.engine == "CYCLES":\n            self.report({"INFO"}, "Samples: " + str(bpy.context.scene.cycles.samples))\n        self.report({"INFO"}, "Resolution: " +\n                              str(bpy.context.scene.render.resolution_x) +\n                               " x " +\n                               str(bpy.context.scene.render.resolution_y))\n        self.report({"INFO"}, "File format: " +\n                               str(bpy.context.scene.render.file_extension))\n        self.report({"INFO"}, "Filepath: " +\n                              str(bpy.context.scene.render.filepath))\n        self.report({"INFO"}, "Frames: " +\n                              str(bpy.context.scene.frame_start) + "-" +\n                              str(bpy.context.scene.frame_end) + ";" +\n                              str(bpy.context.scene.frame_step))\n\n        return {"FINISHED"}\n\n\nbpy.utils.register_class(EngineWarning)\nengine = bpy.context.scene.render.engine\nif engine not in ("BLENDER_RENDER", "CYCLES"):\n    bpy.ops.wm.engine_warning()\n\nbpy.utils.register_class(ShowInformation)\nbpy.ops.wm.scene_information()\n\nbpy.context.scene.render.tile_x = 0\nbpy.context.scene.render.tile_y = 0\nbpy.context.scene.render.resolution_x = 400\nbpy.context.scene.render.resolution_y = 400\nbpy.context.scene.render.resolution_percentage = 100\nbpy.context.scene.render.use_border = True\nbpy.context.scene.render.use_crop_to_border = True\nbpy.context.scene.render.border_max_x = 1.0\nbpy.context.scene.render.border_min_x = 0.0\nbpy.context.scene.render.border_min_y = 0.0\nbpy.context.scene.render.border_max_y = 1.0\nbpy.context.scene.render.use_compositing = bool(False)\nif engine == "CYCLES":\n    samples = 0\n    if samples != 0:\n        bpy.context.scene.cycles.samples = samples\n\n#and check if additional files aren\'t missing\nbpy.ops.file.report_missing_files()\n', 'start_task': 20, 'total_tasks': 20}, 'performance': 46.315309582479095, 'short_description': 'path_root: C:\\Users\\ederenn\\Desktop\\do scenariuszy, start_task: 20, end_task: 20, total_tasks: 20, outfilebasename: scene-Heli20_5, scene_file: /golem/resources/scene-Helicopter-27-cycles.blend', 'src_code': 'from __future__ import print_function\n\nimport os\nimport subprocess\nimport sys\nfrom multiprocessing import cpu_count\n\n# pylint: disable=import-error\nimport params  # This module is generated before this script is run\n\nBLENDER_COMMAND = "blender"\nWORK_DIR = "/golem/work"\nOUTPUT_DIR = "/golem/output"\n\n\ndef exec_cmd(cmd):\n    pc = subprocess.Popen(cmd)\n    return pc.wait()\n\n\n# pylint: disable=too-many-arguments\ndef format_blender_render_cmd(outfilebasename, scene_file, script_file,\n                              start_task, frame, output_format):\n    cmd = [\n        "{}".format(BLENDER_COMMAND),\n        "-b", "{}".format(scene_file),\n        "-y",  # enable scripting by default\n        "-P", "{}".format(script_file),\n        "-o", "{}/{}_{}".format(OUTPUT_DIR, outfilebasename, start_task),\n        "-noaudio",\n        "-F", "{}".format(output_format.upper()),\n        "-t", "{}".format(cpu_count()),\n        "-f", "{}".format(frame)\n    ]\n    return cmd\n\n\n# pylint: disable=too-many-arguments\ndef run_blender_task(outfilebasename, scene_file, script_src, start_task,\n                     frames, output_format):\n    scene_file = os.path.normpath(scene_file)\n    if not os.path.exists(scene_file):\n        print("Scene file \'{}\' does not exist".format(scene_file),\n              file=sys.stderr)\n        sys.exit(1)\n\n    blender_script_path = WORK_DIR + "/blenderscript.py"\n    with open(blender_script_path, "w") as script_file:\n        script_file.write(script_src)\n\n    for frame in frames:\n        cmd = format_blender_render_cmd(outfilebasename, scene_file,\n                                        script_file.name, start_task,\n                                        frame, output_format)\n        print(cmd, file=sys.stderr)\n        exit_code = exec_cmd(cmd)\n        if exit_code is not 0:\n            sys.exit(exit_code)\n\n\nrun_blender_task(params.outfilebasename, params.scene_file, params.script_src,\n                 params.start_task, params.frames, params.output_format)\n\n', 'subtask_id': '9f3f2090-7ed5-11e8-8cb2-fc4f24641c30', 'task_id': '7d7d72cc-7ed5-11e8-aa48-fc4f24641c30', 'working_directory': '.'}], ['package_hash', 'sha1:c1e61f19a32402479e867b389c3dfd06fb74f7d8'], ['size', 8492414], ['concent_enabled', True], ['price', 50000000000000000]])], ['size', 1289691], ['package_hash', 'sha1:fd2c7673d055dfcae017df988266ad40b79b50a7'], ['multihash', 'a712dfaa837d1ba0b933071f750dbbc7e274c2eb0d47c47247e9399884158b1f'], ['secret', b'\x0f(\xb3\x9bn\xe8\xe9\t/c\xfd`\xb8\xe5F\xad\xda\x80\xaa_\xf2\xe5\x82R\xf6\xa7\xe0\xb2\xe5\xea\xf9'], ['options', {'client_id': 'hyperg', 'options': {'peers': [{'TCP': ['35.180.43.86', 3282]}, {'TCP': ['172.31.45.146', 3282]}, {'TCP': ['172.31.45.146', 3282]}, {'TCP': ['172.17.0.1', 3282]}]}, 'version': 1.1}]])]])}) failed'
Traceback (most recent call last):
  File "C:\Users\ederenn\Projects\golem\golem\network\concent\client.py", line 318, in _loop
    concent_variant=self.variant,
  File "C:\Users\ederenn\Projects\golem\golem\network\concent\client.py", line 98, in send_to_concent
    data = golem_messages.dump(msg, signing_key, concent_variant['pubkey'])
  File "C:\Users\ederenn\Projects\golem-env\lib\site-packages\golem_messages\shortcuts.py", line 17, in dump
    return msg.serialize(sign_as=privkey, encrypt_func=encrypt)
  File "C:\Users\ederenn\Projects\golem-env\lib\site-packages\golem_messages\message\base.py", line 311, in serialize
    raise exceptions.SignatureAlreadyExists()
golem_messages.exceptions.SignatureAlreadyExists

[shadeofblue]

this probably happens when the ForceGetTaskResult message is sent the second time (after the timeout) after having been sent the first time earlier...

[PaweuB]

Pivotal: https://www.pivotaltracker.com/story/show/161383687

[dybi]

@shadeofblue - what would be the best way to reproduce? Which test?

[shadeofblue]

@dybi I believe this happens in case of a ForceGetTaskResult message since it has two modes of sending - in one case it's sent directly after a download error and the other if a download doesn't succeed before a timeout happens ...

and I think there are (were?) actually two issues there: 1) the second ForceGetTaskResult was not cancelled after the first was sent (maybe the cancellation of the delayed message happens only on success and is not done on explicit failure) 2) the sending mechanism doesn't check if a signature exists and tries to sign the message the second time