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.

Sign up for GitHub

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

Jump to bottom

Remove 8K limit for single access.log line #332

Closed
wants to merge 12 commits into from
Closed

Remove 8K limit for single access.log line #332

Changes from 1 commit
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
045439f
Removed 8K limit for single log line.
dnevil Nov 14, 2018
35f3acd
Changes as requested for logfilePrintf(). Moved LOGFILE_BUFSZ to Fil…
dnevil Nov 15, 2018
8702c85
Removed thread_local declaration from logfilePrintf().
dnevil Nov 15, 2018
eb12621
Reverted move of LOGFILE_BUFSZ. Simplified code in logfilePrintf().
dnevil Nov 15, 2018
5f3a3eb
Sync prototype of logfileWrite() with definition.
dnevil Nov 15, 2018
3b64034
Merge branch 'master' into log-line-limit
redmeadowman Nov 16, 2018
8bc33c1
Minor change to include ordering.
dnevil Nov 27, 2018
35a46cc
Merge branch 'log-line-limit' of https://github.com/sisic-inc/squid i…
dnevil Nov 27, 2018
f8c25ef
Merge branch 'master' into log-line-limit
redmeadowman Nov 27, 2018
4ead5e0
Add TODO for overflow handling
yadij Feb 11, 2020
fc2501d
Merge branch 'master' into log-line-limit
rousskov Feb 12, 2020
0bdd5a7
Merge branch 'master' into log-line-limit
rousskov Feb 18, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
34 changes: 24 additions & 10 deletions src/log/File.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -112,21 +112,35 @@ void
logfilePrintf(Logfile * lf, const char *fmt,...)
{
va_list args;
char buf[8192];
int s;

va_start(args, fmt);

s = vsnprintf(buf, 8192, fmt, args);

if (s > 8192) {
s = 8192;
// bufsize will be large enough for most log lines
int bufsize = 16 * 1024;
Copy link
Contributor

Choose a reason for hiding this comment

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

Please use size_t for sizes.

char* buf = NULL;

while (true) {
buf = new char[bufsize];
Copy link
Contributor

Choose a reason for hiding this comment

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

We must not allocate and delete memory on every request unless such expensive operations are necessary. This allocation is not necessary AFAICT. For example, we could start with a pre-allocated 16KB on-stack or static buffer and switch to a larger buffer only when needed.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Buffers allocated on stacks are the #1 cause of vulnerabilities in software. It is much safer to allocate memory in the heap. Also, 16K is an excessive amount of memory to allocate on the stack (the former amount was 8K, which is also excessive for the stack). Allocating a static buffer would be fine, but then the function is no longer thread-safe, unless the memory can be allocated with the C++11 thread_local directive.

Copy link
Contributor

Choose a reason for hiding this comment

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

AFAIK, this function does not need to be thread safe. In fact, virtually no Squid function needs to be thread safe except a very small set of specialized functions dedicated to AUFS code (src/DiskIO/DiskThreads/). Outside of threaded AUFS code, virtually any "I will do X because of thread safety" argument is invalid. This logging code is outside of threaded AUFS code.

And if you convert this code to use SBuf, then we do not need to argue whether allocating X KB on stack is "safe" -- SBuf does not use stack for its storage.

if (!buf) {
rousskov marked this conversation as resolved.
Show resolved Hide resolved
break;
}

auto s = vsnprintf(buf, bufsize, fmt, args);
if (s < bufsize) {
logfileWrite(lf, buf, (size_t) s);
delete buf;
yadij marked this conversation as resolved.
Show resolved Hide resolved
break;
}

// Try again with a bigger buffer
Copy link
Contributor

Choose a reason for hiding this comment

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

Please find a way to avoid duplicating SBuf::vappendf() code. For example, it may be possible to reuse a static SBuf buf object in this function instead of all this C-like code.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Agreed.

Copy link
Contributor

Choose a reason for hiding this comment

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

This change request has not been addressed in 35f3acd. There are other problems in that commit as well, but I am going to ignore them until this change request is addressed -- most of the other problems should disappear with this change.

delete buf;
buf = NULL;
yadij marked this conversation as resolved.
Show resolved Hide resolved
bufsize *= 2;
}

if (fmt[strlen(fmt) - 1] == '\n')
buf[8191] = '\n';
if (!buf) {
logfileWrite(lf, (char*)"-", 1);
Copy link
Contributor

@rousskov rousskov Nov 14, 2018 •
edited

Choose a reason for hiding this comment

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

@squid-cache/commiters, besides warning the admin via cache.log, what should we do if an access log line grows insanely big and, hence, should not be allocated and logged "as is"? AFAICT, our options include:

  1. Log a single dash or [...] to allow automated detection/handling but providing no access.log information to track the problem.
  2. Log what we can, possibly misleading automation tools with a truncated field value (e.g., 12 instead of 1234).
  3. Log what we can but append [...] or some other line truncation indicator to allow automated detection/handling.
  4. Split the line into multiple lines, breaking "one transaction, one line" rule.
  5. Truncating largest field(s) as necessary, using option 1, 2, or 3 above for each truncated field.
  6. Allocate until we run out of RAM. See the comment below.

All of the above options except options 5 and 6 break configured logformat.

AFAICT, Squid currently uses option 2. If we cannot agree how to improve/fix the current behavior, this PR should probably preserve it.

I like option 6 the most. What do you think?

Copy link
Contributor

@rousskov rousskov Nov 15, 2018 •
edited

Choose a reason for hiding this comment

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

  1. Needless to say, we can adopt the current PR approach of having no limit at all -- allocate more RAM until Squid is killed by the OS.

This option 6 may actually be the best option because it is simple and OOM deaths caused by this code are rather unlikely. Please note that Squid already keeps pieces of what it wants to log in RAM.

rousskov marked this conversation as resolved.
Show resolved Hide resolved
}

logfileWrite(lf, buf, (size_t) s);
va_end(args);
}

Expand Down