Merge lp:~widelands-dev/widelands/bug-better-syncstreams into lp:widelands

[Notabilis]

Print more information in syncstreams. Create additional smaller syncstream files containing the last few seconds leading to a desync.

[Ready for review and merge]

Since I am not really able to get useful information out of the existing syncstream files, this branch adds further information to the syncstream describing the type of the syncstream entries.

Additionally, create a smaller syncstream extract file next to the syncstream file which contains only the last few seconds. This should be enough to debug the desync but reduces the size of the to-be-uploaded files.

[bunnybot (widelandsofficial)]

Continuous integration builds have changed state:

Travis build 4409. State: failed. Details: https://travis-ci.org/widelands/widelands/builds/481989790.
Appveyor build 4200. State: success. Details: https://ci.appveyor.com/project/widelands-dev/widelands/build/_widelands_dev_widelands_bug_better_syncstreams-4200.

[bunnybot (widelandsofficial)]

Continuous integration builds have changed state:

Travis build 4411. State: passed. Details: https://travis-ci.org/widelands/widelands/builds/482186977.
Appveyor build 4201. State: success. Details: https://ci.appveyor.com/project/widelands-dev/widelands/build/_widelands_dev_widelands_bug_better_syncstreams-4201.

[GunChleoc (gunchleoc)]

I think this is an excellent idea, so I've done a preliminary code review. Let me know when you are finished for a final review.

[Notabilis (notabilis27)]

Thanks for the review. I answered some of your comments below and will push a merge-ready version later on.

[GunChleoc (gunchleoc)]

Answered.

[Notabilis (notabilis27)]

As far as I am concerned, this branch is ready for review and merge now.

[GunChleoc (gunchleoc)]

Code LGTM, not tested

review: Approve

[Notabilis (notabilis27)]

I tested(?) it by enforcing a desync (modifying player.cc and using std::rand() as ID for new economies, then changing economy targets ingame). The new *.wse files were created and could be parsed by the python script. No idea what else can be tested.

[GunChleoc (gunchleoc)]

I have done some similar testing. I'd like to see a few changes:

1. WLApplication:cleanup_replays() does not clean up old wse files
2. There are no instructions in the Python script.
   I'd like to at least see a usage hint when it's called without parameters.

[Notabilis (notabilis27)]

I wrote some documentation, do you think it is understandable and sufficient?

[GunChleoc (gunchleoc)]

Looks good to me, let's have it!

@bunnybot merge

=== modified file 'data/tribes/buildings/productionsites/atlanteans/mill/init.lua'
--- data/tribes/buildings/productionsites/atlanteans/mill/init.lua	2018-09-06 08:21:35 +0000
+++ data/tribes/buildings/productionsites/atlanteans/mill/init.lua	2019-02-10 11:27:32 +0000
@@ -74,7 +74,7 @@
          }
       },
       produce_blackroot_flour = {
-         -- TRANSLATORS: Completed/Skipped/Did not start grinding blackrootbecause ...
+         -- TRANSLATORS: Completed/Skipped/Did not start grinding blackroot because ...
          descname = _"grinding blackroot",
          actions = {
             -- No check whether we need blackroot_flour because blackroots cannot be used for anything else.

=== modified file 'src/economy/economy.cc'
--- src/economy/economy.cc	2019-02-09 08:42:15 +0000
+++ src/economy/economy.cc	2019-02-10 11:27:32 +0000
@@ -711,6 +711,7 @@
 		// alerts, so add info to the sync stream here.
 		{
 			::StreamWrite& ss = game.syncstream();
+			ss.unsigned_8(SyncEntry::kProcessRequests);
 			ss.unsigned_8(req.get_type());
 			ss.unsigned_8(req.get_index());
 			ss.unsigned_32(req.target().serial());
@@ -1051,7 +1052,7 @@
 	// to avoid potential future problems caused by the supplies_ changing
 	// under us in some way.
 	::StreamWrite& ss = game.syncstream();
-	ss.unsigned_32(0x02decafa);  // appears as facade02 in sync stream
+	ss.unsigned_8(SyncEntry::kHandleActiveSupplies);
 	ss.unsigned_32(assignments.size());
 
 	for (const auto& temp_assignment : assignments) {

=== modified file 'src/economy/request.cc'
--- src/economy/request.cc	2018-12-13 07:24:01 +0000
+++ src/economy/request.cc	2019-02-10 11:27:32 +0000
@@ -380,7 +380,7 @@
 	assert(is_open());
 
 	::StreamWrite& ss = game.syncstream();
-	ss.unsigned_32(0x01decafa);  // appears as facade01 in sync stream
+	ss.unsigned_8(SyncEntry::kStartTransfer);
 	ss.unsigned_32(target().serial());
 	ss.unsigned_32(supp.get_position(game)->serial());
 

=== modified file 'src/logic/cmd_queue.cc'
--- src/logic/cmd_queue.cc	2018-12-13 07:24:01 +0000
+++ src/logic/cmd_queue.cc	2019-02-10 11:27:32 +0000
@@ -114,8 +114,7 @@
 
 			if (dynamic_cast<GameLogicCommand*>(&c)) {
 				StreamWrite& ss = game_.syncstream();
-				static uint8_t const tag[] = {0xde, 0xad, 0x00};
-				ss.data(tag, 3);  // provide an easy-to-find pattern as debugging aid
+				ss.unsigned_8(SyncEntry::kRunQueue);
 				ss.unsigned_32(c.duetime());
 				ss.unsigned_32(static_cast<uint32_t>(c.id()));
 			}

=== modified file 'src/logic/filesystem_constants.h'
--- src/logic/filesystem_constants.h	2018-11-09 08:00:35 +0000
+++ src/logic/filesystem_constants.h	2019-02-10 11:27:32 +0000
@@ -49,6 +49,7 @@
 const std::string kReplayDir = "replays";
 const std::string kReplayExtension = ".wrpl";
 const std::string kSyncstreamExtension = ".wss";
+const std::string kSyncstreamExcerptExtension = ".wse";
 // The time in seconds for how long old replays/syncstreams should be kept
 // around, in seconds. Right now this is 4 weeks.
 constexpr double kReplayKeepAroundTime = 4 * 7 * 24 * 60 * 60;

=== modified file 'src/logic/game.cc'
--- src/logic/game.cc	2019-02-09 08:42:15 +0000
+++ src/logic/game.cc	2019-02-10 11:27:32 +0000
@@ -37,6 +37,7 @@
 #include "base/macros.h"
 #include "base/time_string.h"
 #include "base/warning.h"
+#include "build_info.h"
 #include "economy/economy.h"
 #include "game_io/game_loader.h"
 #include "game_io/game_preload_packet.h"
@@ -87,6 +88,8 @@
 void Game::SyncWrapper::start_dump(const std::string& fname) {
 	dumpfname_ = fname + kSyncstreamExtension;
 	dump_.reset(g_fs->open_stream_write(dumpfname_));
+	current_excerpt_id_ = 0;
+	excerpts_buffer_[current_excerpt_id_].clear();
 }
 
 void Game::SyncWrapper::data(void const* const sync_data, size_t const size) {
@@ -114,6 +117,8 @@
 			log("Writing to syncstream file %s failed. Stop synctream dump.\n", dumpfname_.c_str());
 			dump_.reset();
 		}
+		assert(current_excerpt_id_ < kExcerptSize);
+		excerpts_buffer_[current_excerpt_id_].append(static_cast<const char*>(sync_data), size);
 	}
 
 	target_.data(sync_data, size);
@@ -604,6 +609,51 @@
 }
 
 /**
+ * Switches to the next part of the syncstream excerpt.
+ */
+void Game::report_sync_request() {
+	syncwrapper_.current_excerpt_id_ = (syncwrapper_.current_excerpt_id_ + 1) % SyncWrapper::kExcerptSize;
+	syncwrapper_.excerpts_buffer_[syncwrapper_.current_excerpt_id_].clear();
+}
+
+/**
+ * Triggers writing of syncstream excerpt and adds the playernumber of the desynced player
+ * to the stream.
+ * Playernumber should be negative when called by network clients
+ */
+void Game::report_desync(int32_t playernumber) {
+	if (syncwrapper_.dumpfname_.empty()) {
+		log("Error: A desync occurred but no filename for the syncstream has been set.");
+		return;
+	}
+	// Replace .wss extension of syncstream file with .wse extension for syncstream extract
+	std::string filename = syncwrapper_.dumpfname_;
+	assert(syncwrapper_.dumpfname_.length() > kSyncstreamExtension.length());
+	filename.replace(filename.length() - kSyncstreamExtension.length(),
+						kSyncstreamExtension.length(), kSyncstreamExcerptExtension);
+	std::unique_ptr<StreamWrite> file(g_fs->open_stream_write(filename));
+	assert(file != nullptr);
+	// Write revision, branch and build type of this build to the file
+	file->unsigned_32(build_id().length());
+	file->text(build_id());
+	file->unsigned_32(build_type().length());
+	file->text(build_type());
+	file->signed_32(playernumber);
+	// Write our buffers to the file. Start with the oldest one
+	const size_t i2 = (syncwrapper_.current_excerpt_id_ + 1) % SyncWrapper::kExcerptSize;
+	size_t i = i2;
+	do {
+		file->text(syncwrapper_.excerpts_buffer_[i]);
+		syncwrapper_.excerpts_buffer_[i].clear();
+		i = (i + 1) % SyncWrapper::kExcerptSize;
+	} while (i != i2);
+	file->unsigned_8(SyncEntry::kDesync);
+	file->signed_32(playernumber);
+	// Restart buffers
+	syncwrapper_.current_excerpt_id_ = 0;
+}
+
+/**
  * Calculate the current synchronization checksum and copy
  * it into the given array, without affecting the subsequent
  * checksumming process.
@@ -625,6 +675,7 @@
  */
 uint32_t Game::logic_rand() {
 	uint32_t const result = rng().rand();
+	syncstream().unsigned_8(SyncEntry::kRandom);
 	syncstream().unsigned_32(result);
 	return result;
 }

=== modified file 'src/logic/game.h'
--- src/logic/game.h	2018-12-13 07:24:01 +0000
+++ src/logic/game.h	2019-02-10 11:27:32 +0000
@@ -63,6 +63,55 @@
 	gs_ending
 };
 
+// The entry types that are written to the syncstream
+// The IDs are a number in the higher 4 bits and the length in bytes in the lower 4 bits
+// Keep this synchronized with utils/syncstream/syncexcerpt-to-text.py
+enum SyncEntry : uint8_t {
+	// Used in:
+	// game.cc Game::report_desync()
+	// Parameters:
+	// s32 id of desynced user, -1 when written on client
+	kDesync = 0x14,
+	// map_object.cc CmdDestroyMapObject::execute()
+	// u32 object serial
+	kDestroyObject = 0x24,
+	// economy.cc Economy::process_requests()
+	// u8 request type
+	// u8 request index
+	// u32 target serial
+	kProcessRequests = 0x36,
+	// economy.cc Economy::handle_active_supplies()
+	// u32 assignments size
+	kHandleActiveSupplies = 0x44,
+	// request.cc Request::start_transfer()
+	// u32 target serial
+	// u32 source(?) serial
+	kStartTransfer = 0x58,
+	// cmd_queue.cc CmdQueue::run_queue()
+	// u32 duetime
+	// u32 command id
+	kRunQueue = 0x68,
+	// game.h Game::logic_rand_seed()
+	// u32 random seed
+	kRandomSeed = 0x74,
+	// game.cc Game::logic_rand()
+	// u32 random value
+	kRandom = 0x84,
+	// map_object.cc CmdAct::execute()
+	// u32 object serial
+	// u8 object type (see map_object.h MapObjectType)
+	kCmdAct = 0x95,
+	// battle.cc Battle::Battle()
+	// u32 first soldier serial
+	// u32 second soldier serial
+	kBattle = 0xA8,
+	// bob.cc Bob::set_position()
+	// u32 bob serial
+	// s16 position x
+	// s16 position y
+	kBobSetPosition = 0xB8
+};
+
 class Player;
 class MapLoader;
 class PlayerCommand;
@@ -187,9 +236,13 @@
 
 	void logic_rand_seed(uint32_t const seed) {
 		rng().seed(seed);
+		syncstream().unsigned_8(SyncEntry::kRandomSeed);
+		syncstream().unsigned_32(seed);
 	}
 
 	StreamWrite& syncstream();
+	void report_sync_request();
+	void report_desync(int32_t playernumber);
 	Md5Checksum get_sync_hash() const;
 
 	void enqueue_command(Command* const);
@@ -279,7 +332,8 @@
 		     target_(target),
 		     counter_(0),
 		     next_diskspacecheck_(0),
-		     syncstreamsave_(false) {
+		     syncstreamsave_(false),
+		     current_excerpt_id_(0) {
 		}
 
 		~SyncWrapper() override;
@@ -304,6 +358,17 @@
 		std::unique_ptr<StreamWrite> dump_;
 		std::string dumpfname_;
 		bool syncstreamsave_;
+		// Use a cyclic buffer for storing parts of the syncstream
+		// Currently used buffer
+		size_t current_excerpt_id_;
+		// (Arbitrary) count of buffers
+		// Syncreports seem to be requested from the network clients every game second so this
+		// buffer should be big enough to store the last 32 seconds of the game actions leading
+		// up to the desync
+		static constexpr size_t kExcerptSize = 32;
+		// Array of byte buffers
+		// std::string is used as a binary buffer here
+		std::string excerpts_buffer_[kExcerptSize];
 	} syncwrapper_;
 
 	GameController* ctrl_;

=== modified file 'src/logic/map_objects/bob.cc'
--- src/logic/map_objects/bob.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/bob.cc	2019-02-10 11:27:32 +0000
@@ -893,6 +893,7 @@
 	// randomly generated movements.
 	if (upcast(Game, game, &egbase)) {
 		StreamWrite& ss = game->syncstream();
+		ss.unsigned_8(SyncEntry::kBobSetPosition);
 		ss.unsigned_32(serial());
 		ss.signed_16(coords.x);
 		ss.signed_16(coords.y);

=== modified file 'src/logic/map_objects/map_object.cc'
--- src/logic/map_objects/map_object.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/map_object.cc	2019-02-10 11:27:32 +0000
@@ -49,6 +49,7 @@
 }
 
 void CmdDestroyMapObject::execute(Game& game) {
+	game.syncstream().unsigned_8(SyncEntry::kDestroyObject);
 	game.syncstream().unsigned_32(obj_serial);
 
 	if (MapObject* obj = game.objects().get_object(obj_serial))
@@ -94,10 +95,15 @@
 }
 
 void CmdAct::execute(Game& game) {
+	game.syncstream().unsigned_8(SyncEntry::kCmdAct);
 	game.syncstream().unsigned_32(obj_serial);
 
-	if (MapObject* const obj = game.objects().get_object(obj_serial))
+	if (MapObject* const obj = game.objects().get_object(obj_serial)) {
+		game.syncstream().unsigned_8(static_cast<uint8_t>(obj->descr().type()));
 		obj->act(game, arg);
+	} else {
+		game.syncstream().unsigned_8(static_cast<uint8_t>(MapObjectType::MAPOBJECT));
+	}
 	// the object must queue the next CMD_ACT itself if necessary
 }
 

=== modified file 'src/logic/map_objects/tribes/battle.cc'
--- src/logic/map_objects/tribes/battle.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/tribes/battle.cc	2019-02-10 11:27:32 +0000
@@ -65,7 +65,7 @@
 	assert(first_soldier->get_owner() != second_soldier->get_owner());
 	{
 		StreamWrite& ss = game.syncstream();
-		ss.unsigned_32(0x00e111ba);  // appears as ba111e00 in a hexdump
+		ss.unsigned_8(SyncEntry::kBattle);
 		ss.unsigned_32(first_soldier->serial());
 		ss.unsigned_32(second_soldier->serial());
 	}

=== modified file 'src/logic/map_objects/tribes/program_result.h'
--- src/logic/map_objects/tribes/program_result.h	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/tribes/program_result.h	2019-02-10 11:27:32 +0000
@@ -21,6 +21,7 @@
 #define WL_LOGIC_MAP_OBJECTS_TRIBES_PROGRAM_RESULT_H
 
 namespace Widelands {
+// Don't change this values, they are used as hardcoded array indices
 enum ProgramResult { None = 0, Failed = 1, Completed = 2, Skipped = 3 };
 enum ProgramResultHandlingMethod { Fail, Complete, Skip, Continue, Repeat };
 }  // namespace Widelands

=== modified file 'src/logic/map_objects/tribes/worker.cc'
--- src/logic/map_objects/tribes/worker.cc	2018-12-13 07:24:01 +0000
+++ src/logic/map_objects/tribes/worker.cc	2019-02-10 11:27:32 +0000
@@ -2651,7 +2651,7 @@
 	}
 }
 
-/** Check if militray sites have becom visible by now.
+/** Check if militray sites have become visible by now.
  *
  * After the pop in prepare_scouts_worklist,
  * the latest entry of scouts_worklist is the next MS to visit (if known)
@@ -2684,7 +2684,7 @@
                        const Player& player,
                        std::vector<ImmovableFound>& found_sites) {
 
-	// If there are many enemy sites, push a random walk request into queue evry third finding.
+	// If there are many enemy sites, push a random walk request into queue every third finding.
 	uint32_t haveabreak = 3;
 
 	for (const ImmovableFound& vu : found_sites) {

=== modified file 'src/network/gameclient.cc'
--- src/network/gameclient.cc	2018-12-13 07:24:01 +0000
+++ src/network/gameclient.cc	2019-02-10 11:27:32 +0000
@@ -860,6 +860,7 @@
 		int32_t const time = packet.signed_32();
 		d->time.receive(time);
 		d->game->enqueue_command(new CmdNetCheckSync(time, [this] { sync_report_callback(); }));
+		d->game->report_sync_request();
 		break;
 	}
 
@@ -891,8 +892,11 @@
 	case NETCMD_INFO_DESYNC:
 		log("[Client] received NETCMD_INFO_DESYNC. Trying to salvage some "
 		    "information for debugging.\n");
-		if (d->game)
+		if (d->game) {
 			d->game->save_syncstream(true);
+			// We don't know our playernumber, so report as -1
+			d->game->report_desync(-1);
+		}
 		break;
 
 	default:

=== modified file 'src/network/gamehost.cc'
--- src/network/gamehost.cc	2019-02-09 09:03:23 +0000
+++ src/network/gamehost.cc	2019-02-10 11:27:32 +0000
@@ -1875,6 +1875,7 @@
 	}
 
 	log("[Host]: Requesting sync reports for time %i\n", d->syncreport_time);
+	d->game->report_sync_request();
 
 	SendPacket packet;
 	packet.unsigned_8(NETCMD_SYNCREQUEST);
@@ -1916,6 +1917,8 @@
 			    i, d->syncreport.str().c_str(), client.syncreport.str().c_str());
 
 			d->game->save_syncstream(true);
+			// Create syncstream excerpt and add faulting player number
+			d->game->report_desync(i);
 
 			SendPacket packet;
 			packet.unsigned_8(NETCMD_INFO_DESYNC);

=== modified file 'src/wlapplication.cc'
--- src/wlapplication.cc	2018-12-13 07:24:01 +0000
+++ src/wlapplication.cc	2019-02-10 11:27:32 +0000
@@ -1470,6 +1470,13 @@
 		if (is_autogenerated_and_expired(filename)) {
 			log("Delete syncstream %s\n", filename.c_str());
 			g_fs->fs_unlink(filename);
+			assert(filename.length() > kSyncstreamExtension.length());
+			std::string filename_wse = filename.substr(0, filename.length() - kSyncstreamExtension.length());
+			filename_wse += kSyncstreamExcerptExtension;
+			if (g_fs->file_exists(filename_wse)) {
+				log("Delete syncstream excerpt %s\n", filename_wse.c_str());
+				g_fs->fs_unlink(filename_wse);
+			}
 		}
 	}
 

=== added file 'utils/syncstream/syncexcerpt-to-text.py'
--- utils/syncstream/syncexcerpt-to-text.py	1970-01-01 00:00:00 +0000
+++ utils/syncstream/syncexcerpt-to-text.py	2019-02-10 11:27:32 +0000
@@ -0,0 +1,123 @@
+#!/usr/bin/env python3
+
+import struct
+import sys
+
+# WARNING!!
+# Keep this file in sync with the enum SyncEntry in src/logic/game.h
+
+def handle_1(f):
+	print("Desync:")
+	# Read 4 bytes and interprete them as an signed 32 bit integer
+	print("  Desynced player:", struct.unpack('<i', f.read(4))[0])
+
+def handle_2(f):
+	print("DestroyObject:")
+	print("  Serial:", struct.unpack('<I', f.read(4))[0])
+
+def handle_3(f):
+	print("ProcessRequests:")
+	print("  Type:", struct.unpack('<B', f.read(1))[0])
+	print("  Index:", struct.unpack('<B', f.read(1))[0])
+	print("  Serial:", struct.unpack('<I', f.read(4))[0])
+
+def handle_4(f):
+	print("HandleActiveSupplies:")
+	print("  Size:", struct.unpack('<I', f.read(4))[0])
+
+def handle_5(f):
+	print("StartTransfer:")
+	print("  Target serial:", struct.unpack('<I', f.read(4))[0])
+	print("  Source serial:", struct.unpack('<I', f.read(4))[0])
+
+def handle_6(f):
+	print("RunQueue:")
+	print("  Duetime:", struct.unpack('<I', f.read(4))[0])
+	print("  Command:", struct.unpack('<I', f.read(4))[0])
+
+def handle_7(f):
+	print("RandomSeed:")
+	print("  Seed:", struct.unpack('<I', f.read(4))[0])
+
+def handle_8(f):
+	print("Random:")
+	print("  Number:", struct.unpack('<I', f.read(4))[0])
+
+def handle_9(f):
+	print("CmdAct:")
+	print("  Serial:", struct.unpack('<I', f.read(4))[0])
+	# See MapObjectType in map_object.h for decoding the type
+	print("  Actor type:", struct.unpack('<B', f.read(1))[0])
+
+def handle_A(f):
+	print("Battle:")
+	print("  Serial first soldier:", struct.unpack('<I', f.read(4))[0])
+	print("  Serial second soldier:", struct.unpack('<I', f.read(4))[0])
+
+def handle_B(f):
+	print("BobSetPosition:")
+	print("  Serial:", struct.unpack('<I', f.read(4))[0])
+	print("  Position X:", struct.unpack('<h', f.read(2))[0])
+	print("  Position y:", struct.unpack('<h', f.read(2))[0])
+
+handlers = {
+		1: handle_1,
+		2: handle_2,
+		3: handle_3,
+		4: handle_4,
+		5: handle_5,
+		6: handle_6,
+		7: handle_7,
+		8: handle_8,
+		9: handle_9,
+		10: handle_A,
+		11: handle_B
+	}
+
+
+if len(sys.argv) != 2:
+	print("Usage: %s filename.wse > outfile.txt\n" % sys.argv[0])
+
+	print("Parses the hex-data in the given Widelands Syncstream Excerpt")
+	print("into human readable form and echos it to stdout.\n")
+
+	print("You should do this with both the *.wse files of the host and")
+	print("the desyncing client. Which player desynced is also reported")
+	print("at the beginning of the output file of the host.")
+	print("Afterwards, the resulting files can be compared with the")
+	print("'diff' command. For correctly syncronized games the resulting")
+	print("files should be the same, but most likely there will be some")
+	print("small differences in the files (e.g., commands that are only")
+	print("executed for one of the players).")
+	print("There probably will be a large block of commands present at")
+	print("the beginning of only one of the files, this is normal and")
+	print("can be ignored.\n")
+
+	print("To find out more about the commands and where in the Widelands")
+	print("code they are used, see the enum SyncEntry in src/logic/game.h")
+	sys.exit(1)
+
+with open(sys.argv[1], "rb") as f:
+	print("Created with %s(%s)"
+		% (str(f.read(struct.unpack('<I', f.read(4))[0]).decode()),
+		   str(f.read(struct.unpack('<I', f.read(4))[0]).decode())),
+		end='')
+	playernumber = struct.unpack('<i', f.read(4))[0]
+	if playernumber < 0:
+		print(" as client")
+	else:
+		print(" as host, desynced client = %i" % playernumber)
+	byte = f.read(1)
+	while byte:
+		# Parse byte
+		b = ord(byte)
+		cmd = b >> 4
+		length = b & 0x0F
+		if cmd in handlers:
+			handlers[cmd](f)
+		else:
+			# Unknown command. Skip as many bytes as the entry is long
+			print("Warning: Unknown command code '%s', skipping %i bytes" % (cmd, length))
+			for i in range(0, length):
+				byte = f.read(1)
+		byte = f.read(1)