Log tracking issue after server restart

[FliesWithWind]

When server is restarted and new log file is created, it's not being tracked.

Workaround is to restart the bot.

Also some errors appear.

Traceback (most recent call last): File "/home/game2/.local/lib/python3.6/site-packages/bec_rcon.py", line 525, in listenForData traceback.logging.debug_exc() AttributeError: module 'traceback' has no attribute 'logging' Task exception was never retrieved future: <Task finished coro=<ARC.listenForData() done, defined at /home/game2/.local/lib/python3.6/site-packages/bec_rcon.py:496> exception=AttributeError("module 'traceback' has no attribute 'logging'",)> Traceback (most recent call last): File "/home/game2/.local/lib/python3.6/site-packages/bec_rcon.py", line 500, in listenForData answer = self.socket.recv(102400).decode(self.codec) ConnectionRefusedError: [Errno 111] Connection refused

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/home/game2/.local/lib/python3.6/site-packages/bec_rcon.py", line 525, in listenForData traceback.logging.debug_exc() AttributeError: module 'traceback' has no attribute 'logging' Traceback (most recent call last): File "/home/game2/.local/lib/python3.6/site-packages/bec_rcon.py", line 500, in listenForData answer = self.socket.recv(102400).decode(self.codec) ConnectionRefusedError: [Errno 111] Connection refused Reconnecting to BEC Rcon

[Yoshi-E]

I fixed the error in bec_rcon, it has no impact on the bot itself or its actions (is handled, you don’t really need to update), but its now hidden in the bec_rcon error log. You can update it with: pip install --upgrade git+https://github.com/Yoshi-E/Python-BEC-RCon.git -force-reinstall

This however shouldn't be related to the log reading issue. With these bot command you can read function values while the bot is running:

!eval print(bot.cogs['CommandArma'].readLog.getLogs())
!eval print(bot.cogs['CommandArma'].readLog.current_log)
!eval print(bot.cogs['CommandArma'].readLog.currentLinePos)

*Note: The commands return nothing, it only prints it into the bots console (and not into the bots log file) Does it return the current log? Is the currentLinePos > 0?

[FliesWithWind]

Sorry it's been a while, had some sever issues on the way and stopped using the bot for a while.

Here's the output of the commands.

After the restart the new log file is named same as old one, therefor it keeps reading it. However the line position is wrong. Maybe an optional log rescan / reset after bot reconnection could solve it (if it won't affect other bot processes)?

exec 'print(bot.cogs['CommandArma'].readLog.getLogs())'
['arma3server-console-2021-11-26-04:30:01.log', 'arma3server-console-2021-11-27-04:30:01.log', 'arma3server-console-2021-11-27-17:35:01.log', 'arma3server-console-2021-11-28-04:30:01.log', 'arma3server-console-2021-11-28-13:55:01.log', 'arma3server-console-2021-11-28-18:20:01.log', 'arma3server-console-2021-11-28-21:45:01.log', 'arma3server-console-2021-11-29-04:30:02.log', 'arma3server-console-2021-11-30-04:30:01.log', 'arma3server-console-2021-12-01-04:30:01.log', 'arma3server-console-2021-12-01-21:05:01.log', 'arma3server-console-2021-12-02-04:30:01.log', 'arma3server-console-2021-12-03-04:30:01.log', 'arma3server-console.log']
exec 'print(bot.cogs['CommandArma'].readLog.current_log)'
arma3server-console.log
exec 'print(bot.cogs['CommandArma'].readLog.currentLinePos)'
188681

wc -l log/console/arma3server-console.log
6190 log/console/arma3server-console.log

[Yoshi-E]

Doing it after bot reconnection is not recommended, as it could get stuck in an infinite loop, causing massive IOPS on the hardrive.

Instead the implemented bug fix triggers a reset of the log file cursor if the file size reduces, e.g. after the creation of a new empty log file.

I did not extensively test this, so please report any errors.

[FliesWithWind]

It seems it does not detect the change of the logfile after the restart. The restart is not done by the bot btw.

I'm guessing maybe it's not throwing any exceptions there?

exec 'print(bot.cogs['CommandArma'].readLog.getLogs())'
['arma3server-console-2021-11-28-13:55:01.log', 'arma3server-console-2021-11-28-18:20:01.log', 'arma3server-console-2021-11-28-21:45:01.log', 'arma3server-console-2021-11-29-04:30:02.log', 'arma3server-console-2021-11-30-04:30:01.log', 'arma3server-console-2021-12-01-04:30:01.log', 'arma3server-console-2021-12-01-21:05:01.log', 'arma3server-console-2021-12-02-04:30:01.log', 'arma3server-console-2021-12-03-04:30:01.log', 'arma3server-console-2021-12-04-04:30:01.log', 'arma3server-console-2021-12-04-08:51:09.log', 'arma3server-console-2021-12-04-11:50:01.log', 'arma3server-console-2021-12-05-04:30:01.log', 'arma3server-console-2021-12-06-04:30:01.log', 'arma3server-console-2021-12-06-10:50:01.log', 'arma3server-console.log']
exec 'print(bot.cogs['CommandArma'].readLog.current_log)'
arma3server-console.log
exec 'print(bot.cogs['CommandArma'].readLog.currentLinePos)'
20026

wc -l log/console/arma3server-console.log
4911 log/console/arma3server-console.log

Not sure if it's the correct syntax but maybe catching this exception could be used to reset logposition.

exec 'print(bot.cogs['CommandArma'].readLog.processLogLine(20026))'
Traceback (most recent call last):
  File "/home/game1/ArmaRconDiscordBot/modules/arma/readLog.py", line 230, in processLogLine
    timestamp, msg = self.splitTimestamp(line)
  File "/home/game1/ArmaRconDiscordBot/modules/arma/readLog.py", line 296, in splitTimestamp
    m = re.match(r"^\s?([0-9]{1,2}:[0-9]{2}:[0-9]{2})\s(.*)", log_line)
  File "/usr/lib/python3.6/re.py", line 172, in match
    return _compile(pattern, flags).match(string)
TypeError: expected string or bytes-like object

expected string or bytes-like object
None

[Yoshi-E]

Are you sure you implemented my patch db0d1115427866f5f0899a9cc13567e061ef0767 and waited long enough? The files are only checked once every 60s.

The function "watch_log" works in the following way:

1. A log file is opened as a datastream. CODE
2. The file will be read until the EOF is reached. Each line (string data) will be processed with "processLogLine". CODE
3. Now the currentLinePos is e.g. 1000, the end of the file.
4. As the server restarts, the file is emptied, as a "new" log is created.
5. The file cursor now tries to read line 1001, which does not exists, as the file is now much shorter. CODE
6. If after 60s line 1001 still does not exists, it will check if a new log file was created CODE
7. If no new log file was created, it now compares the "currentLinePos" to the actual file length of the active log file. Is the currentLinePos outside the actual lenght of the active log file, it will be read from the beginning. CODE

If that did not work, maybe test and see if this code block is properly called after 60s, and where is perhaps fails.

[Yoshi-E]

I think I found the cause, will push a fix later today

[FliesWithWind]

Great! I've added some debugging logs today, but will have results with possible cause tomorrow.

[Yoshi-E]

The issue stems from a unique Linux behavior when dealing with files: On Linux/Unix systems, once a process has a handle on a file, it can read it, even if the file is deleted.

Meaning the bot is reading the deleted "arma3server-console.log" when a new "arma3server-console.log" already exists.

At least for the log reader, the files are now identified by the disk inode number, rather than just file name.

Please test this tweak and see if it works for you.

[FliesWithWind]

I've tested it and it seems to be solved.

Thanks!