Version 2.2.0 - "BACKBLAZE_CALL" messages

Support
#1

I did the update to 2.2.0 version and when performing some small test backups to B2 I got several lines with status code 404:

TRACE BACKBLAZE_CALL [1] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/cc/e304ac3c6ca52bcdd29838269f9ec8581c988986c7308bf739f25b1841baff' returned status code 404

At the end the backup seems to occur without major problems.

As the B2 backend was changed in this latest version (as in the example below), I thought I’d better to highlight that the message level has been modified from DEBUG to TRACE.

-		LOG_**DEBUG**("BACKBLAZE_CALL", "URL request '%s %s' returned status code %d", method, url, response.StatusCode)

+ 		e := &B2Error{}
+		if err := json.NewDecoder(response.Body).Decode(e); err != nil {
+			LOG_**TRACE**("BACKBLAZE_CALL", "[%d] URL request '%s %s' returned status code %d", threadIndex, method, requestURL, response.StatusCode)
+		} else {
+			LOG_**TRACE**("BACKBLAZE_CALL", "[%d] URL request '%s %s' returned %d %s", threadIndex, method, requestURL, response.StatusCode, e.Message)
+		}
#2

I’m trying to understand the logic of these “404” messages (file not found). Notice the times in the log lines:

New files identified, ok:

...
2019-05-07 09:36:46.649 TRACE PACK_START Packing [redacted]
2019-05-07 09:36:46.649 INFO PACK_END [redacted]
2019-05-07 09:36:46.649 TRACE PACK_START Packing [redacted]
2019-05-07 09:36:46.649 INFO PACK_END Packed [redacted]

Duplication check (I think) if these chunks related to these files exist in B2, obviously don’t exist, then returns the code 404, ok:

2019-05-07 09:36:47.650 TRACE BACKBLAZE_CALL [3] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/96/026187e19bb68a45b521e9026844bd939893ba9c756e6151245eab7f864340' returned status code 404
2019-05-07 09:36:47.654 TRACE BACKBLAZE_CALL [0] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/50/354dec04a50360cdff9142b03aa237679a69d6d3b17d5167d8fe6384457c03' returned status code 404

Chunks don’t exist, then upload,ok:

2019-05-07 09:37:02.545 INFO UPLOAD_PROGRESS Uploaded chunk 1 size 644955, 75KB/s 00:00:12 58.1%
2019-05-07 09:37:09.081 INFO UPLOAD_PROGRESS Uploaded chunk 3 size 888329, 90KB/s 00:00:01 100.0%

The sequence above is perfect.

But, in the same log (after the above sequence), there are other “404” messages:

2019-05-07 09:37:10.022 TRACE BACKBLAZE_CALL [1] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/cc/e304ac3c6ca52bcdd29838269f9ec8581c988986c7308bf739f25b1841baff' returned status code 404
2019-05-07 09:37:10.025 TRACE BACKBLAZE_CALL [0] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/c5/d9fa95e9d3b6a0095963a5aaa13a06da50da33017347561c0fc2ce73ed49cf' returned status code 404
2019-05-07 09:37:10.944 TRACE BACKBLAZE_CALL [5] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/b9/238828255a34658215bff558cd3c08b95ab0c521df03834ba44b57e3c0db5c' returned status code 404
2019-05-07 09:37:10.945 TRACE BACKBLAZE_CALL [4] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/81/fa586d6972afcdd79f3567bf290fecfc1f7d80d55ce273719c80a3a8fcaccc' returned status code 404
2019-05-07 09:37:11.140 TRACE BACKBLAZE_CALL [2] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/a9/be3da9a0337bbb2957012928885e4396a23dd02392f12eb272e1bd654a4c3e' returned status code 404
2019-05-07 09:37:11.140 TRACE BACKBLAZE_CALL [3] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/3d/8e8d832cf91102125280bccf97e2211c8407ee6804131dd792b89d99bd35f7' returned status code 404
2019-05-07 09:37:11.375 TRACE BACKBLAZE_CALL [7] URL request 'HEAD https://f001.backblazeb2.com/file/[redacted]/chunks/98/804a73d8041cb70f2643011b271bfa9bbf98a3251be0eb60c0c745cfc651ae' returned status code 404

But no other record of Uploaded chunk, and looking directly at B2, these chunks are there, and looks like been created in this backup run (by the timestamp).

And at the end of the log:

2019-05-07 09:37:45.216 INFO BACKUP_STATS Files: 24366 total, 1,219M bytes; 95 new, 2,073K bytes
2019-05-07 09:37:45.216 INFO BACKUP_STATS File chunks: 1036 total, 1,227M bytes; 2 new, 1,497K bytes, 1,458K bytes uploaded
2019-05-07 09:37:45.216 INFO BACKUP_STATS Metadata chunks: 7 total, 6,834K bytes; 7 new, 6,834K bytes, 2,398K bytes uploaded
2019-05-07 09:37:45.216 INFO BACKUP_STATS All chunks: 1043 total, 1,233M bytes; 9 new, 8,331K bytes, 3,856K bytes uploaded

Note: the check command reports that everything is ok, all chuncks of all revisions are in storage.

So I have 9 “404” messages but only 2 “upload” messages. I didn’t understand…

#4

The other 7 404 messages were for these 7 metadata chunks. When metadata chunks are being uploaded there aren’t any UPLOAD_PROGRESS messages.

2 Likes