Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

nsq_to_file: support for separate working dir for in-progress files #1110

Merged
merged 1 commit into from
Jan 2, 2019
Merged

nsq_to_file: support for separate working dir for in-progress files #1110

merged 1 commit into from
Jan 2, 2019

Conversation

mccutchen
Copy link
Contributor

The problem

There are a couple of edge cases we currently need to guard against when shipping the archive files generated by nsq_to_file to remote storage (e.g. S3).

  1. Skipping files for the current hour to which nsq_to_file is actively writing incoming messages. This requires our sync scripts to know how nsq_to_file will be bucketing files by time, so they can manually exclude the current bucket.
  2. Skipping corrupted gzip files that can arise from the combination of using nsq_to_file -gzip and an unclean exit (e.g. kill -9). We don't currently have a good workaround for this issue, which causes issues in downstream systems and requires manual intervention to remediate.

Proposed change

If nsq_to_file used a separate "working dir" for the files to which it is actively writing and only moved files into the final output dir once they were cleanly finished/closed, the problems above would be much easier to address:

  1. We no longer need special logic to skip "active" files, because files that appear in the output dir are guaranteed to be finished and ready to upload
  2. While corrupted gzip files are still possible, they will never show up in the output dir. A separate process could watch the working dir for orphaned files, allowing for alerts, simpler manual remediation, and even automated recovery.

Implementation details

If -work-dir is given, nsq_to_file will create new files under that directory and only move them to -output-dir upon close, ensuring that only fully finished and synced files appear in the output dir.

By default, the work dir will match the output dir in order to preserve existing behavior out of the box.

@jehiah
Copy link
Member

jehiah commented Dec 5, 2018

👍 in general (haven't looked at the code yet of course). I've run into these same pain points to varying degrees.

A separate working directory would make it easy to monitor for any old files in the working directory and manually recover them (remove corrupt gzip blocks with data that will end up in other files)

@mccutchen
Copy link
Contributor Author

A separate working directory would make it easy to monitor for any old files in the working directory and manually recover them (remove corrupt gzip blocks with data that will end up in other files)

Yep, that's exactly what we're thinking!

Copy link
Member

@jehiah jehiah left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 one minor detail

apps/nsq_to_file/file_logger.go Outdated Show resolved Hide resolved
@jehiah jehiah added the feature label Dec 5, 2018
jehiah
jehiah previously approved these changes Dec 5, 2018
Copy link
Member

@jehiah jehiah left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍 squash away. Anything else you want to do here before this lands?

@mccutchen
Copy link
Contributor Author

Ahhhhh dang I just realized this change is unsafe as-is and should not be merged! (I'd dismiss the approval if I could.)

If an nsq_to_file process is cleanly restarted, it will move its current file from the work dir to the output dir and then re-open a new file in the workdir with the exact same name because the logic for bumping <REV> won't see the finished files in the output dir. Then, once the time bucket rolls over, the new working file will overwrite the existing file with the same name.

I'm not sure if that explanation makes sense as written, but here's a sort of illustration:

/tmp/nsqout
└── foo
    ├── foo.2018-12-05_22-41+0000.rig-000000.log.gz
    ├── foo.2018-12-05_22-42+0000.rig-000000.log.gz
    ├── foo.2018-12-05_22-43+0000.rig-000000.log.gz
    └── foo.2018-12-05_22-44+0000.rig-000000.log.gz  # <-- moved to output dir on clean restart
/tmp/nsqwork
└── foo
    └── foo.2018-12-05_22-44+0000.rig-000000.log.gz  # <-- new working file w/ same name, will overwrite file above

Note: The current minute is included in these filenames to speed up the testing process; full command line is:

~/nsq_to_file -topic=foo -gzip -output-dir=/tmp/nsqout -work-dir=/tmp/nsqwork -filename-format="<TOPIC>/<TOPIC>.<DATETIME>+0000.<HOST><REV>.log" -nsqd-tcp-address=:4150 -datetime-format="%Y-%m-%d_%H-%M"

@mreiferson
Copy link
Member

mreiferson commented Dec 5, 2018

Good catch, feel like we should perform a similar check at rename time as we do here (and cycle through revision numbers)?

@jehiah jehiah dismissed their stale review December 6, 2018 03:54

dismissing per follow up information

@ploxiln
Copy link
Member

ploxiln commented Dec 7, 2018

Great idea, and great catch.

I don't think we can use the exact same filename conflict logic, since this bit is not opening a new file to write to, it's moving to a new name:

 		if f.gzipEnabled {
 			openFlag |= os.O_EXCL
 		} else {
 			openFlag |= os.O_APPEND
 		}
 		f.out, err = os.OpenFile(absFilename, openFlag, 0666)
 		if err != nil {
			if os.IsExist(err) {
				continue  // to next rev name

I think there's no O_EXCL like flag for Rename() (in Go or Posix or Linux). So it'll be slightly different, we'll have to just stat the dst filepath.

@mccutchen
Copy link
Contributor Author

Heh, I was literally just talking to 🐍 about this offline. I was initially afraid that, because os.Rename() will overwrite the destination if it exists, it would be difficult to atomically check destination existence & rename.

It turns out there's a cool trick for this that was not obvious to me: make a hard link to the destination first, and only if that succeeds delete the source. If the hard link fails, the destination already exists and we need to pick a new file name.

@ploxiln
Copy link
Member

ploxiln commented Dec 7, 2018

ah, very cool 👍

@jehiah
Copy link
Member

jehiah commented Dec 7, 2018

I think i dislike the "rename on move" approach (or at least relying on that in entirety). I think we should pick initial name based on unused names between both directories. (even though it introduces some race condition issues if you were to run more than one nsq_to_file against the same directory, it should be safe outside of that).

I like the property that a filename is "unique" and constant once it's opened. That means that if you kill -9 nsq_to_file you still have a uniquely named file in the working directory to recover and don't have to do extra work to figure out if it was a duplicate file or not where that filename might already appear elsewhere.

In practice I think this means aos.Stat on output-dir before the os.Create against work-dir when iterating to find an available filename.

@mreiferson
Copy link
Member

After thinking this through a bit, I agree that optimistically checking both dirs is a useful addition.

However, I'd like nsq_to_file to be confidently race free and operator-friendly in avoiding data loss, so I think it's useful to preserve the behavior @mccutchen is introducing to perform a conflict-free rename. In other words, it will ensure that nsq_to_file will never overwrite a file in the output dir.

The question is then, what should nsq_to_file's behavior be if it does detect a conflict? @jehiah's suggesting that it shouldn't automatically rename. I'm fine with keeping things simple, which I suppose would be to "do nothing" by logging the conflict and leaving the file in the working dir?

WDYT @mccutchen @jehiah?

@jehiah
Copy link
Member

jehiah commented Dec 7, 2018

If we check both directories to pick a unique filename up front in the normal case, i'm ok with the possibility of a rename on move to guarantee a path to resolve conflicts at that time.

@mccutchen
Copy link
Contributor Author

👍 cool, I'll take a pass at this

@mccutchen
Copy link
Contributor Author

Okay, with the latest commits, I think I've implemented the approach described above. Please take another look!

There's a bit of awkwardness/duplication in the code (e.g. safely munging file paths, duplicated log messages, not-quite-the-same overlap in functionality when iterating through revs) so all suggestions for improvements are welcome.

I'm gonna bang on this locally a bit more to try to ensure I'm not missing any edge cases.

@mccutchen
Copy link
Contributor Author

Meh, sorry for the noise, but I have spotted a bug when choosing a new file name when there's a conflict in the output dir. Note that the minute changed from 17 to 18 in the file name listed below:

2018/12/07 22:18:00 INFO: renamed finished file /tmp/nsqwork/foo/foo.2018-12-07_22-17+0000.rig-000001.log.gz to /tmp/nsqout/foo/foo.2018-12-07_22-18+0000.rig-000001.log.gz to avoid overwrite

@mccutchen
Copy link
Contributor Author

Okay, I think this change is functionally complete and working as expected, though the code itself is not very pretty. Please take another look when y'all get a chance @jehiah @mreiferson @ploxiln.

@mccutchen
Copy link
Contributor Author

Also, to give myself a bit more confidence in the new behavior here, I spent the weekend over-engineering this jepsen-lite test program to exercise these changes:
https://gist.github.com/mccutchen/174bf5681264871644dfb5b8ec079cd9

An example run:

$ go run nsq_to_file_jepsen.go 
2018/12/11 16:33:45 =============================================================
2018/12/11 16:33:45 setup
2018/12/11 16:33:45 =============================================================
2018/12/11 16:33:45 removing working dir /var/folders/4m/qzsqvqqj2p5gcn_ygxdpv8q00000gn/T/nsq-to-file-test157817500 (if it exists)
2018/12/11 16:33:45 creating working dir /var/folders/4m/qzsqvqqj2p5gcn_ygxdpv8q00000gn/T/nsq-to-file-test157817500
2018/12/11 16:33:45 nsqd and nsq_to_file logs combined in /var/folders/4m/qzsqvqqj2p5gcn_ygxdpv8q00000gn/T/nsq-to-file-test157817500/logs.txt
2018/12/11 16:33:45 running nsqd
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:46 running nsq_to_file for topic "foo", restarting every 10s
2018/12/11 16:33:47 =============================================================
2018/12/11 16:33:47 generating messages
2018/12/11 16:33:47 =============================================================
2018/12/11 16:33:47 publishing 100000 messages over 3m0s
2018/12/11 16:33:47 nsq_to_file stats: 1 messages; 0 channel depth, 1 in flight
2018/12/11 16:33:52 nsq_to_file stats: 3640 messages; 0 channel depth, 257 in flight
2018/12/11 16:33:57 nsq_to_file stats: 7296 messages; 0 channel depth, 645 in flight
2018/12/11 16:34:02 nsq_to_file stats: 11051 messages; 0 channel depth, 1663 in flight
2018/12/11 16:34:07 nsq_to_file stats: 14681 messages; 0 channel depth, 528 in flight
2018/12/11 16:34:12 nsq_to_file stats: 18376 messages; 0 channel depth, 856 in flight
2018/12/11 16:34:17 nsq_to_file stats: 22006 messages; 0 channel depth, 429 in flight
2018/12/11 16:34:22 nsq_to_file stats: 25661 messages; 0 channel depth, 705 in flight
2018/12/11 16:34:27 nsq_to_file stats: 29293 messages; 0 channel depth, 303 in flight
2018/12/11 16:34:32 nsq_to_file stats: 32960 messages; 0 channel depth, 603 in flight
2018/12/11 16:34:37 nsq_to_file stats: 36597 messages; 0 channel depth, 182 in flight
2018/12/11 16:34:42 nsq_to_file stats: 40241 messages; 0 channel depth, 438 in flight
2018/12/11 16:34:47 nsq_to_file stats: 43988 messages; 0 channel depth, 84 in flight
2018/12/11 16:34:52 nsq_to_file stats: 47663 messages; 0 channel depth, 384 in flight
2018/12/11 16:34:57 nsq_to_file stats: 51359 messages; 0 channel depth, 98 in flight
2018/12/11 16:35:02 nsq_to_file stats: 55059 messages; 0 channel depth, 1607 in flight
2018/12/11 16:35:07 nsq_to_file stats: 58707 messages; 0 channel depth, 339 in flight
2018/12/11 16:35:12 nsq_to_file stats: 62149 messages; 0 channel depth, 1489 in flight
2018/12/11 16:35:17 nsq_to_file stats: 65710 messages; 0 channel depth, 1511 in flight
2018/12/11 16:35:22 nsq_to_file stats: 69226 messages; 0 channel depth, 1376 in flight
2018/12/11 16:35:27 nsq_to_file stats: 72891 messages; 0 channel depth, 325 in flight
2018/12/11 16:35:32 nsq_to_file stats: 76565 messages; 0 channel depth, 1500 in flight
2018/12/11 16:35:37 nsq_to_file stats: 80217 messages; 0 channel depth, 268 in flight
2018/12/11 16:35:42 nsq_to_file stats: 83899 messages; 0 channel depth, 1342 in flight
2018/12/11 16:35:47 nsq_to_file stats: 87559 messages; 0 channel depth, 685 in flight
2018/12/11 16:35:52 nsq_to_file stats: 91165 messages; 0 channel depth, 1395 in flight
2018/12/11 16:35:57 nsq_to_file stats: 94816 messages; 0 channel depth, 1509 in flight
2018/12/11 16:36:02 nsq_to_file stats: 98285 messages; 0 channel depth, 1601 in flight
2018/12/11 16:36:07 nsq_to_file stats: 100000 messages; 0 channel depth, 1293 in flight
2018/12/11 16:36:12 nsq_to_file stats: 100000 messages; 0 channel depth, 0 in flight
2018/12/11 16:36:12 nsqd fully drained
2018/12/11 16:36:12 stopping nsqd
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 stopping nsq_to_file
2018/12/11 16:36:12 =============================================================
2018/12/11 16:36:12 report
2018/12/11 16:36:12 =============================================================
2018/12/11 16:36:12 success: found exactly 100000 messages in 170 output files
2018/12/11 16:36:12 output dir: /var/folders/4m/qzsqvqqj2p5gcn_ygxdpv8q00000gn/T/nsq-to-file-test157817500/output

Copy link
Member

@ploxiln ploxiln left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great. Made note of two little things, sort of conversationally, no real need to change them.

makeOutputDir(outputFileName)

_, err := os.Stat(outputFileName)
if err == nil || os.IsExist(err) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would guess that you should never get an error here (including an Exist error). But this seems very safe, and clear.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, during normal operation this conditional should never be true.

The os.IsExist case covers an unlikely but possible scenario (I think!) where some entirely other process adds a file to the final output dir that has the same name as an in-progress file in the working dir, in a sequence of events along these lines:

  • Two (or more) nsq_to_file processes are sharing the same working and output dirs
  • One process is kill -9'd, orphaning a file in the working dir
  • A separate cleanup process scans the working dir for orphaned files and moves the file into a tmp dir for cleanup/processing
  • The killed nsq_to_file process starts back up and picks the same file name as the orphaned file (because it's no longer present in either work dir or output dir)
  • The cleanup process finishes processing and naively (or buggily) sticks the orphaned file into the output dir under the same name
  • The restarted nsq_to_file process now has to safely pick a new filename at the point where it's trying to move the file from working dir to output dir

I think the sequence above is quite unlikely, but, as you said, I think guarding against it isn't too onerous!

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just mean, if the file exists, I suspect the stat will never return an error, it will be the err == nil case.

}
}

func atomicRename(src, dst string) error {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I might have called this exclusiveRename() because the file does exist in two places for a moment, and because it emulates the open(..., O_EXCL), but this is also fine.

@mccutchen
Copy link
Contributor Author

mccutchen commented Dec 12, 2018 via email

Copy link
Member

@mreiferson mreiferson left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, let's squash???????

If -work-dir is given, nsq_to_file will create new files under that
directory and only move them to -output-dir upon close, ensuring that
only fully finished and synced files appear in the output dir.

Work dir will match output dir by default in order to preserve existing
behavior out of the box.
@mccutchen
Copy link
Contributor Author

Squashed and rebased, but the latter step seems to have angered the code coverage tests. Clicking through to the failing build, I'm not sure the failure has anything to do with these changes.

@mreiferson
Copy link
Member

it can be noisy, nbd

thanks!

@mreiferson mreiferson merged commit 45d0a35 into nsqio:master Jan 2, 2019
@mccutchen mccutchen deleted the nsq-to-file-workdir branch January 3, 2019 01:10
@mreiferson mreiferson mentioned this pull request Jan 3, 2019
@boxy-robot
Copy link

We're finally making moves to use this feature. @mreiferson could we cut a new nsq release to get this included sometime soon? I think the latest release is 1.1.0 on Aug 19, 2018

@mreiferson
Copy link
Member

You’re saying you want me to actually touch a computer?

@boxy-robot
Copy link

Will send brisket in exchange. Or the frozen turkeys @mccutchen loves so much.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants