[MAGNOLIA-5591] Generate timestamp for activation as close to actual transfer as possible Created: 04/Nov/13 Updated: 10/Feb/14 Resolved: 04/Feb/14 |
|
| Status: | Closed |
| Project: | Magnolia |
| Component/s: | activation |
| Affects Version/s: | 4.5.14 |
| Fix Version/s: | 4.5.16 |
| Type: | Bug | Priority: | Major |
| Reporter: | Joerg von Frantzius | Assignee: | Jaroslav Simak |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | maintenance, support | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Issue Links: |
|
||||||||||||||||||||||||
| Template: |
|
||||||||||||||||||||||||
| Acceptance criteria: |
Empty
|
||||||||||||||||||||||||
| Task DoD: |
[ ]*
Doc/release notes changes? Comment present?
[ ]*
Downstream builds green?
[ ]*
Solution information and context easily available?
[ ]*
Tests
[ ]*
FixVersion filled and not yet released
[ ] 
Architecture Decision Record (ADR)
|
||||||||||||||||||||||||
| Bug DoR: |
[ ]*
Steps to reproduce, expected, and actual results filled
[ ]*
Affected version filled
|
||||||||||||||||||||||||
| Release notes required: |
Yes
|
||||||||||||||||||||||||
| Date of First Response: | |||||||||||||||||||||||||
| Description |
|
In info.magnolia.module.exchangesimple.BaseSyndicatorImpl.transportActivatedData(ActivationContent, URLConnection, String), a timestamp of current author time is gathered, and later on sent to public instances together with the activation request. The activation request is then refused by the public instance if the public's current time diverges from this author timestamp by more than 30s, presumably in order to verify author and public clocks are in sync. Unfortunately, the timestamp on author is created before the temporary file with activation data is created in Transporter.transport(). Given a recursive activation with huge amounts of binary data (multiple GB) plus some load on author and public, these 30s can too easily be exceeded. The timestamp on author should be created as shortly as possible before the actual sending of the activation HTTP request. Otherwise, the clock sync check will fail when creating the temp file takes longer than 30s, which probably isn't desired. |
| Comments |
| Comment by Jan Haderka [ 05/Nov/13 ] |
|
actually dumping content into the temp file on the disk should be the small chunk of time in the activation. The most time is consumed by sending data over, so even if timestamp is generated afterwards it would not help, unless you have disks that are actually slower then network connection itself. |
| Comment by Joerg von Frantzius [ 05/Nov/13 ] |
|
Gigabit ethernet in theory shouldn't be slower than the harddrive, I'd hope. I'm not sure what's happening on the receiving end, though, is it the Multipartfilter that receives the data? Does it cache it in RAM? (And anyway I thought you'd want the activation to fail when clocks diverge, not when writing content to disk takes longer than activationDelayTolerance) |
| Comment by Jan Haderka [ 05/Nov/13 ] |
On the contrary I would hope that disk is still way too faster then network.
It's sent over as multipart so indeed what happens in public depends on configuration of multipart filter. There is definitively space for improvement.
Ideally i would not want to fail even if clock diverge, only if someone captured that request and tries to replay it later. And I'm not saying this is not an issue. I think your point is valid, I'm just trying to hint that maybe there are other things in the affected system that could/should be optimised as well. |
| Comment by Joerg von Frantzius [ 05/Nov/13 ] |
|
OK, does that mean info.magnolia.module.exchangesimple.ReceiveFilter.checkTimestamp(String[]) only exists so activation requests cannot be replayed? Just today we were wondering what this check is good for, and if maybe it has something to do with transactional activation. The error message seemed to say that clocks need to be sync, so I thought clocks being in sync was important for activation to work. (BTW, Wikipedia on HDD transfer rates says "As of 2010, a typical 7,200-rpm desktop HDD has a sustained "disk-to-buffer" data transfer rate up to 1,030 Mbits/sec.", which would be roughly 1 Gigabit/sec for read access (write access should be even slower). |
| Comment by Joerg von Frantzius [ 06/Nov/13 ] |
|
BTW is it correct that the temporary file is written again for each subscriber? So if I activate 500MB to 4 public nodes, then the whole activation will write 2GB temporary files? |
| Comment by Jan Haderka [ 06/Nov/13 ] |
|
We are getting little bit off-topic here, but it's nevertheless entertaining.
Well that was 2010, now it's 2013, the traditional disks got better with never SATA controller versions since and many servers
Yes, it seems so. Well spotted. That should be changed. I believe that it is probably derelict since the time that activation content was indeed different per public instance because it contained other now irrelevant stuff as well.
The only purpose of this check is to prevent someone capturing the communication between servers and replaying it later. Imagine you activate a page, attacker in the middle captures that, later once you make modifications to that page and activate them, attacker would simply replay the original activation to effectively wipe out your changes. This is what this check is guarding against. |
| Comment by Jan Haderka [ 06/Nov/13 ] |
|
BTW what kind of 500MB files are you storing on the server? Is this really good idea to serve those from Magnolia? Do you provide simple http links to those files from the web? If so, don't you end up blocking one http executor thread per each download? Since it takes while to download 500MB (assuming consumers are not on your internal 1GB network) you are in extreme cases severely limiting throughput of the server no? |
| Comment by Joerg von Frantzius [ 06/Nov/13 ] |
|
Sorry it's a folder in the DMS containing a lot of PDFs, which together amount to 500MB. |
| Comment by Joerg von Frantzius [ 06/Nov/13 ] |
I allowed myself to open |
| Comment by Jan Haderka [ 06/Nov/13 ] |
|
I see, but then each of those PDF files is activated separately, not together with the parent folder so the 30 second timeout is per file. Assuming "a lot" is at least 100 that would be on average 5MB per file … that should not take 30 seconds. |
| Comment by Joerg von Frantzius [ 07/Nov/13 ] |
|
I just turned on DEBUG logging for info.magnolia.module.exchangesimple, and this is what happens when I activated a folder containing the PDFs. (BTW I did not choose "including subfolders") First it creates temporary files for each of the PDFs contained in the folder and stores them in the filesystem path returned by Path.getTempDirectory(): 13-11-07 09:33:17 DEBUG AUTHOR[Thread-52]info.magnolia.module.exchangesimple.ResourceCollector: Preparing content dms:/bsintern/pibs-001 for publishing. 13-11-07 09:33:17 DEBUG AUTHOR[Thread-52]info.magnolia.module.exchangesimple.ResourceCollector: Preparing content dms:/bsintern/pibs-001/MetaData for publishing. 13-11-07 09:33:17 DEBUG AUTHOR[Thread-52]info.magnolia.module.exchangesimple.ResourceCollector: Preparing content dms:/bsintern/pibs-001/document for publishing. 13-11-07 09:33:18 DEBUG AUTHOR[Thread-52]info.magnolia.module.exchangesimple.ResourceCollector: Preparing content dms:/bsintern/pibs-001/description_files for publishing. 13-11-07 09:33:18 DEBUG AUTHOR[Thread-52]info.magnolia.module.exchangesimple.ResourceCollector: Preparing content dms:/bsintern/pibs-001/description_files/MetaData for publishing. (pibs-001 is a DMS document containing the PDF) And then it creates one giant temporary file (390M) in /tmp that contains them all and sends it over to the publics: 13-11-07 09:33:18 DEBUG AUTHOR[Thread-55]info.magnolia.module.exchangesimple.BaseSyndicatorImpl: activate 13-11-07 09:33:18 DEBUG AUTHOR[Thread-55]info.magnolia.module.exchangesimple.BaseSyndicatorImpl: Exchange : sending activation request to magnoliaPublic8080 with user superuser 13-11-07 09:33:18 DEBUG AUTHOR[Thread-55]info.magnolia.module.exchangesimple.Transporter: prepareTempFile() /tmp/13838131980642683567536218306597.mgnl_activation 13-11-07 09:34:52 DEBUG AUTHOR[Thread-55]info.magnolia.module.exchangesimple.BaseSyndicatorImpl: Exchange : activation request sent to magnoliaPublic8080 13-11-07 09:34:54 DEBUG AUTHOR[Thread-56]info.magnolia.module.exchangesimple.BaseSyndicatorImpl: Debugging is enabled. Keeping temporary files in store for debugging purposes. Clean the store manually once done with debugging. 13-11-07 09:34:55 INFO AUTHOR[Thread-52]info.magnolia.module.exchangesimple.BaseSyndicatorImpl: Exchange: activation succeeded [/bsintern] (I put a breakpoint before the file is deleted in info.magnolia.module.exchangesimple.Transporter.transport(HttpURLConnection, ActivationContent) and looked at its size. BTW that temporary file is deleted even though BaseSyndicatorImpl says "Keeping temporary files in store for debugging purposes.") So the PDFs aren't sent over individually, but in one go. Preparing the 390M temp file and sending it over must be faster than 30s in order not to fail. |
| Comment by Jan Haderka [ 07/Nov/13 ] |
Ahh, but that is the REAL bug. When you activate folder without sub content, only folder should get activated not it's content. If you say "Activate incl sub items" it will activate one by one as it should and you will not run into 30seconds timeout.
Indeed. Message tells you that there will be some garbage that is normally cleaned out automatically, but that is useful to find out what is going on when there are issues when sending content from one instance to another or also useful if you want to emulate activation in tests w/o having one or the other instance. It never made claim to keep all files created around. |
| Comment by Jaroslav Simak [ 04/Feb/14 ] |