Bug 7640 - Client log handling broken with simultaneous clients on Windows
Summary: Client log handling broken with simultaneous clients on Windows
Status: CLOSED FIXED
Alias: None
Product: ThinLinc
Classification: Unclassified
Component: Client (show other bugs)
Version: trunk
Hardware: PC Unknown
: P2 Normal
Target Milestone: 4.13.0
Assignee: Linn
URL:
Keywords: nikle_tester, relnotes
Depends on:
Blocks:
 
Reported: 2021-02-09 15:31 CET by Pierre Ossman
Modified: 2021-06-30 09:06 CEST (History)
2 users (show)

See Also:
Acceptance Criteria:
Running only 1 client: * On startup, previous .log-file(s) should be renamed to .old.log. * Should only be one .log file present Running >=2 clients at the same time: * Make sure client 1 to 9 get a separate .log-file. If more than 9 clients are started, the additional ones should not have any log file belonging to them. * If a client is closed and another client is started *without* closing all clients, we should "reuse" the names of logfiles. - Scenario: We close client A that was using tlc.log, and open up another client B. tlc.log should then be renamed to tlc.old.log, and the client B should use tlc.log as its log file. No matter how many clients have been open at the same time, once they are *all* closed and we open up a new client: - All previous .old.log files should be removed - All previous .log files should be renamed as .old.log * Make sure that the line with the process id always is in the log file regardless of loglevel is used


Attachments

Description Pierre Ossman cendio 2021-02-09 15:31:34 CET
When we start the client we first rename any old "tlclient.log" to "tlclient.old.log". On Linux and macOS this works reliably, but on Windows this can fail.

The reason it can fail on Windows is because we cannot rename it if the log file is still open. E.g. when you open two clients at the same time.

Since the file cannot be renamed as intended, we can also get a broken log file as two (or more) processes try to write to the same file.
Comment 2 Linn cendio 2021-02-18 12:51:37 CET
To be able to fulfil the acceptance criteria, clients on Linux and Mac must to be able to see if the log file is locked or otherwise in use. I have found two methods that seem to work the same way on Linux and Mac - flock(2) and fcntl(2). Below are summary of them, as well as their pros and cons. 


flock(2):
 * Only for advisory locks.
 * Does not lock files over NFS.
 * Duplicated file descriptors refer to the same lock.
 
+ Advisory locks are enough
+ File descriptors are allowed to refer to the same lock
- Unclear what not locking files over NFS means. We only need to be able to keep track of locks made on a specific machine, not keep track of locks on several machines.


fcntl(2):
 * For both advisory and mandatory locks, but mandatory locking is unreliable due to race conditions.
 * Works for locking files over NFS.
 * Locks only a segment of the file.
 * Duplicated file descriptors refer to the same open file description (i.e. they share the same file status flags).
 
+ Advisory locks are enough
+ Works over NFS
- Ideally we would like to lock the whole file, but how do we do that when it is expanding? Alternatively, it might be enough to just lock a part of the file to indicate that it is in use.
Comment 3 Linn cendio 2021-03-10 15:37:33 CET
A different approach would be to identify which log file that is active by saving the process id it is started on, and check if that process id is still running. 

It is not a perfect solution since process id:s can be reused, but its a sufficiently good method for this corner case. The worst case scenario is that a log file will be cleaned up later (when a new client is started and the other process has ended) rather than right away.


We decided to use the approach with process ids to implement this since it seemed less complex while still fulfilling our requirements.
Comment 5 Linn cendio 2021-03-11 13:45:21 CET
Some tips for testing not mentioned in the acceptance criteria:

* When only using one client at a time, no difference should be noticed from how the log files previously worked
* Not obvious how to open several clients on mac, ask if needed
Comment 9 Linn cendio 2021-03-15 09:17:46 CET
I have tested the acceptance criteria for jenkins build #1866 on Fedora 32, Windows 10 and MacOS 11 and did not find any issues.
Comment 10 Niko Lehto cendio 2021-03-15 16:15:30 CET
I could reproduce this issue with 4.12.0 on Windows 10. And tested the solution with Nightly build (6777).
Tested on Windows 10, Fedora 33 and macOS 11.

Tested acceptance criterias:
>Running only 1 client: 
>* On startup, previous .log-file(s) should be renamed to .old.log.
>* Should only be one .log file present
OK

>Running >=2 clients at the same time: 
>* Make sure client 1 to 9 get a separate .log-file. If more than 9 clients are >started, the additional ones should not have any log file belonging to them.
>* If a client is closed and another client is started *without* closing all >clients, we should "reuse" the names of logfiles.
OK

>No matter how many clients have been open at the same time, once they are *all* >closed and we open up a new client:
>- All previous .old.log files should be removed
>- All previous .log files should be renamed as .old.log
OK, note that all previous .old.log files will be removed at all times when a new client is started (Even if all clients were *not* previously closed).

Also worth noting that this change affects handling of log files on all platforms and not just Windows.

Relnotes looks good. Documentation looks good, but we might want to include some information that we are re-using log filenames if the log file is inactive.
Comment 11 Linn cendio 2021-03-23 16:02:20 CET
Added an acceptance criterion for checking that the line with the process always is written to the log file. This is because the implementation is dependent on the information from that line, and it should always be there no matter what the loglevel is set to.

The loglevel can be 1-5. Run this to start a client with specific loglevel:
> tlclient -d <loglevel>
Comment 22 Linn cendio 2021-03-24 14:41:09 CET
Various small fixes has been done to the code. I have tested on Fedora 33, Windows and Mac and it seems to be working well.

Tester should be wary of the additional acceptance criterion related to loglevel, see comment 11 for extra info.
Comment 31 Linn cendio 2021-04-08 08:53:00 CEST
This bug is now ready for testing. I have tested on Fedora 33, Windows 10 and MacOS 11 and did not find any issues.

Since last testing there have been changes to how the log file is opened as well as changes in both Windows and Unix logic, so the tester has to retest all acceptance criteria on all platforms.
Comment 32 Niko Lehto cendio 2021-04-08 17:09:08 CEST
Tested this on build containing these changes. Tested on Windows 10, macOS and Fedora 33.

>Running only 1 client: 
>* On startup, previous .log-file(s) should be renamed to .old.log.
>* Should only be one .log file present
OK

>Running >=2 clients at the same time: 
>* Make sure client 1 to 9 get a separate .log-file. If more than 9 clients are >started, the additional ones should not have any log file belonging to them.
>* If a client is closed and another client is started *without* closing all >clients, we should "reuse" the names of logfiles.
OK

>No matter how many clients have been open at the same time, once they are *all* >closed and we open up a new client:
>- All previous .old.log files should be removed
>- All previous .log files should be renamed as .old.log
OK

> Make sure that the line with the process id always is in the log file regardless of loglevel is used
OK, The line "Log file created for ThinLinc client running on process <PID>" is always present

Documentation and relnotes looks good too!

Note You need to log in before you can comment on or make changes to this bug.