How to get sync gateway 1.1.0 to open new log file after logrotate?

Mobile Sync Gateway
1

I cannot get logrotate to work with sync gateway v1.1.0, it just keeps a file pointer to the old file and the size continues to grow with a ton of null at the beginning of the log file. With v1.0.3 it worked fine by using the following logrotate config file (it was scheduled to rotate every hour):

/var/log/sync-gateway.log {
    dateext
    dateformat -%s
    rotate 20
    size 10M
    missingok
    notifempty
    compress
    copytruncate
    postrotate
        kill -HUP `pidof sync_gateway`
    endscript
}

When I upgraded to sync gateway v1.1.0 it stopped working, and sync gateway would hold on to the same location in the old log file, so I would end up with a huge file that had a ton of null at the beginning. I tried changing it to the recommended log rotate config from the documentation (http://developer.couchbase.com/documentation/mobile/1.1.0/develop/guides/sync-gateway/deployment/in-production/index.html) but this doesn’t work either:

/var/log/sync-gateway.log {
dateext
dateformat -%s
rotate 20
size 10k
missingok
notifempty
compress
copytruncate
postrotate
    /usr/bin/pkill -HUP sync_gateway
endscript

}

I tried with ‘> /dev/null’ appended to the kill command and without it and it failed either way. How do I configure sync gateway v1.1.0 to do the log rotate properly? I’m on Ubuntu.

Thanks,
Alex

2

I can see this in the new log file that has a ton of empty lines at the top:

2015-09-03T14:22:34.061Z HTTP:  #24230: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.062Z HTTP:  #24231: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.064Z HTTP:  #24232: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.065Z HTTP:  #24233: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3029927  (as eb75318a-8d73-4259-b37c-66ff04c794c2)
2015-09-03T14:22:34.070Z HTTP:  #24235: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.070Z HTTP:  #24237: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.071Z HTTP:  #24236: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024764  (as c6ff070d-92be-4642-a3cc-4a0abb0bf1b7)
2015-09-03T14:22:34.071Z HTTP:  #24234: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3021377  (as b07958d8-77aa-4d8c-ada9-2ed67f1ed18e)
2015-09-03T14:22:34.073Z HTTP:  #24238: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.080Z SIGHUP: Reloading Config....
2015-09-03T14:22:34.084Z HTTP:  #24240: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3023617  (as bf97ee79-0580-4523-b229-5a5f0459fa4e)
2015-09-03T14:22:34.093Z HTTP:  #24241: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.102Z HTTP:  #24239: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3002286  (as 2d0b0c34-ddf2-4700-95b8-e1d0af8831b5)
2015-09-03T14:22:34.103Z HTTP:  #24242: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3024172  (as c222b18b-afd2-4e40-8bea-09dc9d07ffbf)
2015-09-03T14:22:34.103Z HTTP:  #24243: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3004975  (as 41d1fedb-1144-4816-9f39-2572cd3fcbf4)
2015-09-03T14:22:34.105Z HTTP:  #24244: GET /todos/_changes?feed=longpoll&limit=50&heartbeat=300000&style=all_docs&since=3030511  (as ef659656-24f9-47e4-9837-a096f8dfcec5)

The longpoll requests are because the android lite client is insane and makes multiple requests per second, regardless of whether or not the app is running in the foreground or background, and that’s why the sync gateway logs fill up so fast. But I can see in the middle of those requests that it says “Reloading Config…”, which is what I usually see when I send the kill -HUP signal. Isn’t that supposed to start a new log file, instead of continuing at the same location in the old one?

3

@alexegli

I’m trying to repro this on a VM on Ubuntu 14.

To use the new log rotation feature in 1.1.0, there are three steps:

  1. Start SG with the -logFilePath argument instead of using stderr redirect

sync_gateway -logFilePath=sg_error.log sync_gateway.json

  1. remove the ‘copy truncate’ option from the log rotate config

  2. Add the ‘postrotate’ option to the log rotate config

It looks like you have not done step 2? it might be this that is causing the behaviour you are seeing

Andy

4

Thanks, that fixed it. My bad, I should have read the documentation closer.