test_log_files.py (6810B)
1 # This Source Code Form is subject to the terms of the Mozilla Public 2 # License, v. 2.0. If a copy of the MPL was not distributed with this 3 # file, You can obtain one at http://mozilla.org/MPL/2.0/. 4 5 import os 6 from urllib.parse import quote 7 8 from marionette_driver import Wait, errors 9 from marionette_harness import MarionetteTestCase, WindowManagerMixin 10 11 12 def inline(doc): 13 return f"data:text/html;charset=utf-8,{quote(doc)}" 14 15 16 class TestSessionRestoreLogging(WindowManagerMixin, MarionetteTestCase): 17 def setUp(self): 18 super().setUp() 19 self.marionette.enforce_gecko_prefs({ 20 "browser.sessionstore.loglevel": "Debug", 21 "browser.sessionstore.log.appender.file.logOnSuccess": True, 22 }) 23 24 def tearDown(self): 25 try: 26 # Create a fresh profile for subsequent tests. 27 self.marionette.restart(in_app=False, clean=True) 28 finally: 29 super().tearDown() 30 31 def getSessionFilePath(self): 32 profilePath = self.marionette.instance.profile.profile 33 assert profilePath is not None 34 return os.path.join(profilePath, "sessionstore.jsonlz4") 35 36 def getLogDirectoryPath(self): 37 profilePath = self.marionette.instance.profile.profile 38 assert profilePath is not None 39 return os.path.join(profilePath, "sessionstore-logs") 40 41 def cleanupLogDirectory(self): 42 dirPath = self.getLogDirectoryPath() 43 for fname in self.getLogFiles(): 44 fpath = os.path.join(dirPath, fname) 45 os.remove(fpath) 46 47 def getLogFiles(self, matchstr=""): 48 dirPath = self.getLogDirectoryPath() 49 fileNames = [] 50 if os.path.isdir(dirPath): 51 fileNames = [entry.name for entry in os.scandir(dirPath) if entry.is_file()] 52 # Optionally filter by substring 53 if len(matchstr) > 0 and len(fileNames) > 0: 54 fileNames = filter(lambda name: matchstr in name, fileNames) 55 return fileNames 56 57 def getMostRecentLogFile(self, matchstr=""): 58 dirPath = self.getLogDirectoryPath() 59 # Build full paths 60 files = [os.path.join(dirPath, f) for f in self.getLogFiles(matchstr)] 61 # Get the newest file by creation time 62 return max(files, key=os.path.getctime) if len(files) > 0 else None 63 64 def openAndCloseSaveworthyWindow(self): 65 urls = ( 66 inline("""<div">ipsum</div>"""), 67 inline("""<div">dolor</div>"""), 68 ) 69 self.marionette.set_context("chrome") 70 origWindow = self.marionette.current_window_handle 71 win = self.open_window(private=False) 72 self.marionette.switch_to_window(win) 73 with self.marionette.using_context("content"): 74 for index, url in enumerate(urls): 75 if index > 0: 76 tab = self.open_tab() 77 self.marionette.switch_to_window(tab) 78 self.marionette.navigate(url) 79 self.marionette.execute_script("window.close()") 80 self.marionette.switch_to_window(origWindow) 81 82 def getLineCount(self, logFile): 83 with open(logFile) as f: 84 return sum(1 for _ in f) 85 86 def test_per_startup_logfile_creation(self): 87 self.marionette.quit() 88 self.cleanupLogDirectory() 89 self.marionette.start_session() 90 self.marionette.set_context("chrome") 91 self.marionette.quit() 92 93 # There were no errors so we just expect the success log file to have been created 94 self.assertEqual( 95 len(self.getLogFiles()), 96 1, 97 "Exactly one log file was created after a restart and quit", 98 ) 99 self.marionette.start_session() 100 101 def test_errors_flush_to_disk(self): 102 self.marionette.enforce_gecko_prefs({ 103 "browser.sessionstore.log.appender.file.logOnSuccess": False, 104 }) 105 self.marionette.quit() 106 sessionFile = self.getSessionFilePath() 107 self.assertTrue( 108 os.path.isfile(sessionFile), 109 "The sessionstore.jsonlz4 file exists in the profile directory", 110 ) 111 # replace the contents with nonsense so we get a not-readable error on startup 112 with open(sessionFile, "wb") as f: 113 f.write(b"\x00\xff\xabgarbageDATA") 114 115 self.marionette.start_session() 116 self.marionette.set_context("chrome") 117 118 errorLogFile = self.getMostRecentLogFile("error-") 119 self.assertTrue(errorLogFile, "We logged errors immediately") 120 121 if os.path.isfile(sessionFile): 122 os.remove(sessionFile) 123 124 def test_periodic_flush_to_disk(self): 125 # enable debug logging and verify that log messages are batched 126 # and only flush when the interval has passed 127 logFile = self.getMostRecentLogFile() 128 logFileCount = len(self.getLogFiles()) 129 self.assertTrue(logFile, "A log file already exists") 130 self.assertEqual(logFileCount, 1, "A single 'success' log file exists") 131 startLineCount = self.getLineCount(logFile) 132 133 # open and close a window 134 self.openAndCloseSaveworthyWindow() 135 136 self.assertEqual( 137 self.getLineCount(logFile), 138 startLineCount, 139 "Log file line count unchanged; debug messages should be buffered and not yet flushed to disk", 140 ) 141 142 # Set the flush interval to 1 second and open+close another window to trigger some 143 # debug log messages 144 self.marionette.set_pref("browser.sessionstore.logFlushIntervalSeconds", 1) 145 origWindow = self.marionette.current_window_handle 146 self.openAndCloseSaveworthyWindow() 147 148 try: 149 wait = Wait(self.marionette, timeout=5, interval=0.1) 150 wait.until( 151 lambda _: self.getLineCount(logFile) > startLineCount, 152 message="Waiting for line count in the log file to grow", 153 ) 154 newLineCount = self.getLineCount(logFile) 155 self.assertTrue( 156 newLineCount > startLineCount, 157 f"{newLineCount - startLineCount} lines got flushed to the log file", 158 ) 159 except errors.TimeoutException as e: 160 message = ( 161 f"{e.message}. Line count didn't grow as expected in log file {logFile}" 162 ) 163 raise errors.TimeoutException(message) 164 finally: 165 self.marionette.switch_to_window(origWindow) 166 self.marionette.clear_pref("browser.sessionstore.logFlushIntervalSeconds") 167 168 self.assertTrue( 169 self.getLineCount(logFile) > startLineCount, 170 "Debug log messages got flushed to disk", 171 ) 172 self.assertEqual( 173 len(self.getLogFiles()), 174 logFileCount, 175 "We just appended to the one log file and didn't create any others", 176 )