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.

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

Can not find any logs in Grafana Explorer #75

Open
Garfield550 opened this issue Aug 30, 2021 · 12 comments
Open

Can not find any logs in Grafana Explorer #75

Garfield550 opened this issue Aug 30, 2021 · 12 comments

Comments

@Garfield550
Copy link

I run Grafana Loki in my host machine using Docker, and I have a worker program also running in Docker.

CONTAINER ID   IMAGE                        COMMAND                  CREATED       STATUS       PORTS                                                           NAMES
fe033b5de44b   grafana/grafana-enterprise   "/run.sh"                2 hours ago   Up 2 hours   0.0.0.0:3333->3000/tcp, :::3333->3000/tcp                       grafana
f023d89739e1   grafana/promtail:2.3.0       "/usr/bin/promtail -…"   6 days ago    Up 6 days                                                                    condescending_goodall
4e1a1d5122c7   grafana/loki:2.3.0           "/usr/bin/loki -conf…"   6 days ago    Up 6 days    0.0.0.0:3100->3100/tcp, :::3100->3100/tcp                       adoring_johnson

I set up Winston Loki use follow configs:

new LokiTransport({
  level: 'verbose',
  json: true,
  labels: { job: 'MetaCMSWorkerGit' },
  host: 'http://172.17.0.1:3100',
  handleExceptions: true,
  handleRejections: true,
}),

In worker docker stdout, I can saw LokiTransport options, batcher and pushLogEntry has correct value (I add some console log into winston-loki package):

LokiTransport options: {
  level: 'verbose',
  json: true,
  labels: { job: 'MetaCMSWorkerGit' },
  host: 'http://172.17.0.1:3100',
  handleExceptions: true,
  handleRejections: true
}
this.batcher: {
  level: 'verbose',
  json: true,
  labels: { job: 'MetaCMSWorkerGit' },
  host: 'http://172.17.0.1:3100',
  handleExceptions: true,
  handleRejections: true
}
winston:create-logger: Define prototype method for "error"
winston:create-logger: Define prototype method for "warn"
winston:create-logger: Define prototype method for "info"
winston:create-logger: Define prototype method for "http"
winston:create-logger: Define prototype method for "verbose"
winston:create-logger: Define prototype method for "debug"
winston:create-logger: Define prototype method for "silly"
pushLogEntry: {
  labels: { level: 'info', job: 'MetaCMSWorkerGit' },
  entries: [
    {
      ts: '08/30/2021, 10:59:31 AM',
      line: 'Log files saved to /tmp/metacmsworkergit-WH1oq6 {"host":"","runtime":{"pid":320463,"platform":"linux","versions":{"node":"14.17.3","v8":"8.4.371.23-node.67","uv":"1.41.0","zlib":"1.2.11","brotli":"1.0.9","ares":"1.17.1","modules":"83","nghttp2":"1.42.0","napi":"8","llhttp":"2.1.3","openssl":"1.1.1k","cldr":"39.0","icu":"69.1","tz":"2021a","unicode":"13.0"}},"context":"main","ms":"+0ms"}'
    }
  ]
}
winston:file: written true false

But I can not find any log in Grafana Explorer, did I missed something?

image

@Garfield550
Copy link
Author

Maybe http.request not send anything

image

winston:file: ENOENT ok /tmp/metacmsworkergit-mQyU2X/verbose.log
winston:file: stat done: verbose.log { size: 0 }
winston:file: create stream start /tmp/metacmsworkergit-mQyU2X/verbose.log { flags: 'a' }
winston:file: create stream ok /tmp/metacmsworkergit-mQyU2X/verbose.log
winston:file: ENOENT ok /tmp/metacmsworkergit-mQyU2X/error.log
winston:file: stat done: error.log { size: 0 }
winston:file: create stream start /tmp/metacmsworkergit-mQyU2X/error.log { flags: 'a' }
winston:file: create stream ok /tmp/metacmsworkergit-mQyU2X/error.log
winston:file: file open ok /tmp/metacmsworkergit-mQyU2X/verbose.log
winston:file: file open ok /tmp/metacmsworkergit-mQyU2X/error.log
winston:rejection: finished
winston:file: close /tmp/metacmsworkergit-mQyU2X/error.log 4623
winston:rejection: doExit true
winston:rejection: process._exiting false
winston-loki:requests:data {"streams":[{"stream":{"level":"info","job":"MetaCMSWorkerGit"},"values":[["1630391658055000000","Log files saved to /tmp/metacmsworkergit-mQyU2X {\"host\":\"\",\"runtime\":{\"pid\":359302,\"platform\":\"linux\",\"versions\":{\"node\":\"14.17.3\",\"v8\":\"8.4.371.23-node.67\",\"uv\":\"1.41.0\",\"zlib\":\"1.2.11\",\"brotli\":\"1.0.9\",\"ares\":\"1.17.1\",\"modules\":\"83\",\"nghttp2\":\"1.42.0\",\"napi\":\"8\",\"llhttp\":\"2.1.3\",\"openssl\":\"1.1.1k\",\"cldr\":\"39.0\",\"icu\":\"69.1\",\"tz\":\"2021a\",\"unicode\":\"13.0\"}},\"context\":\"main\",\"ms\":\"+0ms\"}"]]},{"stream":{"level":"error","job":"MetaCMSWorkerGit"},"values":[["1630391658874000000","unhandledRejection: Can not find WORKER_SECRET env\nError: Can not find WORKER_SECRET env\n    at new HttpRequestService (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/api/index.ts:12:22)\n    at bootstrap (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts:9:16)\n    at Object.<anonymous> (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts:27:1)\n    at Module._compile (internal/modules/cjs/loader.js:1085:14)\n    at Module.m._compile (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts:1311:23)\n    at Module._extensions..js (internal/modules/cjs/loader.js:1114:10)\n    at Object.require.extensions.<computed> [as .ts] (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts:1314:12)\n    at Module.load (internal/modules/cjs/loader.js:950:32)\n    at Function.Module._load (internal/modules/cjs/loader.js:790:14)\n    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:76:12) {\"error\":{},\"stack\":\"Error: Can not find WORKER_SECRET env\\n    at new HttpRequestService (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/api/index.ts:12:22)\\n    at bootstrap (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts:9:16)\\n    at Object.<anonymous> (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts:27:1)\\n    at Module._compile (internal/modules/cjs/loader.js:1085:14)\\n    at Module.m._compile (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts:1311:23)\\n    at Module._extensions..js (internal/modules/cjs/loader.js:1114:10)\\n    at Object.require.extensions.<computed> [as .ts] (/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts:1314:12)\\n    at Module.load (internal/modules/cjs/loader.js:950:32)\\n    at Function.Module._load (internal/modules/cjs/loader.js:790:14)\\n    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:76:12)\",\"exception\":true,\"date\":\"Tue Aug 31 2021 06:34:18 GMT+0000 (Coordinated Universal Time)\",\"process\":{\"pid\":359302,\"uid\":1002,\"gid\":1002,\"cwd\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git\",\"execPath\":\"/home/garfield/.nvm/versions/node/v14.17.3/bin/node\",\"version\":\"v14.17.3\",\"argv\":[\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/.bin/ts-node\",\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts\"],\"memoryUsage\":{\"rss\":336011264,\"heapTotal\":238084096,\"heapUsed\":207135648,\"external\":6836432,\"arrayBuffers\":529642}},\"os\":{\"loadavg\":[0.22,0.09,0.09],\"uptime\":613718.49},\"trace\":[{\"column\":22,\"file\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/api/index.ts\",\"function\":\"new HttpRequestService\",\"line\":12,\"method\":null,\"native\":false},{\"column\":16,\"file\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts\",\"function\":\"bootstrap\",\"line\":9,\"method\":null,\"native\":false},{\"column\":1,\"file\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/src/main.ts\",\"function\":null,\"line\":27,\"method\":null,\"native\":false},{\"column\":14,\"file\":\"internal/modules/cjs/loader.js\",\"function\":\"Module._compile\",\"line\":1085,\"method\":\"_compile\",\"native\":false},{\"column\":23,\"file\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts\",\"function\":\"Module.m._compile\",\"line\":1311,\"method\":\"_compile\",\"native\":false},{\"column\":10,\"file\":\"internal/modules/cjs/loader.js\",\"function\":\"Module._extensions..js\",\"line\":1114,\"method\":\".js\",\"native\":false},{\"column\":12,\"file\":\"/home/garfield/Projects/Work/Meta/meta-cms-worker-git/node_modules/ts-node/src/index.ts\",\"function\":\"Object.require.extensions.<computed> [as .ts]\",\"line\":1314,\"method\":\"ts]\",\"native\":false},{\"column\":32,\"file\":\"internal/modules/cjs/loader.js\",\"function\":\"Module.load\",\"line\":950,\"method\":\"load\",\"native\":false},{\"column\":14,\"file\":\"internal/modules/cjs/loader.js\",\"function\":\"Module._load\",\"line\":790,\"method\":\"_load\",\"native\":false},{\"column\":12,\"file\":\"internal/modules/run_main.js\",\"function\":\"Function.executeUserEntryPoint [as runMain]\",\"line\":76,\"method\":\"executeUserEntryPoint [as runMain]\",\"native\":false}],\"host\":\"\",\"runtime\":{\"pid\":359302,\"platform\":\"linux\",\"versions\":{\"node\":\"14.17.3\",\"v8\":\"8.4.371.23-node.67\",\"uv\":\"1.41.0\",\"zlib\":\"1.2.11\",\"brotli\":\"1.0.9\",\"ares\":\"1.17.1\",\"modules\":\"83\",\"nghttp2\":\"1.42.0\",\"napi\":\"8\",\"llhttp\":\"2.1.3\",\"openssl\":\"1.1.1k\",\"cldr\":\"39.0\",\"icu\":\"69.1\",\"tz\":\"2021a\",\"unicode\":\"13.0\"}},\"context\":\"main\",\"ms\":\"+820ms\"}"]]}]}
winston-loki:requests:req ClientRequest {
  _events: [Object: null prototype] {
    response: [Function: bound onceWrapper] { listener: [Function (anonymous)] },
    error: [Function (anonymous)]
  },
  _eventsCount: 2,
  _maxListeners: undefined,
  outputData: [
    {
      data: 'POST /loki/api/v1/push HTTP/1.1\r\n' +
        'Content-Type: application/json\r\n' +
        'Content-Length: 5518\r\n' +
        'Host: 172.17.0.1:3100\r\n' +
        'Connection: close\r\n' +
        '\r\n',
      encoding: 'latin1',
      callback: null
    },
    {
      data: <Buffer 7b 22 73 74 72 65 61 6d 73 22 3a 5b 7b 22 73 74 72 65 61 6d 22 3a 7b 22 6c 65 76 65 6c 22 3a 22 69 6e 66 6f 22 2c 22 6a 6f 62 22 3a 22 4d 65 74 61 43 ... 5468 more bytes>,
      encoding: undefined,
      callback: undefined
    },
    {
      data: '',
      encoding: 'latin1',
      callback: [Function: bound onFinish]
    }
  ],
  outputSize: 5649,
  writable: true,
  destroyed: false,
  _last: true,
  chunkedEncoding: false,
  shouldKeepAlive: false,
  _defaultKeepAlive: true,
  useChunkedEncodingByDefault: true,
  sendDate: false,
  _removedConnection: false,
  _removedContLen: false,
  _removedTE: false,
  _contentLength: null,
  _hasBody: true,
  _trailer: '',
  finished: true,
  _headerSent: true,
  socket: null,
  _header: 'POST /loki/api/v1/push HTTP/1.1\r\n' +
    'Content-Type: application/json\r\n' +
    'Content-Length: 5518\r\n' +
    'Host: 172.17.0.1:3100\r\n' +
    'Connection: close\r\n' +
    '\r\n',
  _keepAliveTimeout: 0,
  _onPendingData: [Function: noopPendingOutput],
  agent: Agent {
    _events: [Object: null prototype] {
      free: [Function (anonymous)],
      newListener: [Function: maybeEnableKeylog]
    },
    _eventsCount: 2,
    _maxListeners: undefined,
    defaultPort: 80,
    protocol: 'http:',
    options: { path: null },
    requests: {},
    sockets: { '172.17.0.1:3100:': [Array] },
    freeSockets: {},
    keepAliveMsecs: 1000,
    keepAlive: false,
    maxSockets: Infinity,
    maxFreeSockets: 256,
    scheduling: 'lifo',
    maxTotalSockets: Infinity,
    totalSocketCount: 1,
    [Symbol(kCapture)]: false
  },
  socketPath: undefined,
  method: 'POST',
  maxHeaderSize: undefined,
  insecureHTTPParser: undefined,
  path: '/loki/api/v1/push',
  _ended: false,
  res: null,
  aborted: false,
  timeoutCb: null,
  upgradeOrConnect: false,
  parser: null,
  maxHeadersCount: null,
  reusedSocket: false,
  host: '172.17.0.1',
  protocol: 'http:',
  [Symbol(kCapture)]: false,
  [Symbol(kNeedDrain)]: false,
  [Symbol(corked)]: 0,
  [Symbol(kOutHeaders)]: [Object: null prototype] {
    'content-type': [ 'Content-Type', 'application/json' ],
    'content-length': [ 'Content-Length', 5518 ],
    host: [ 'Host', '172.17.0.1:3100' ]
  }
}
error Command failed with exit code 1.

@Garfield550
Copy link
Author

If I use curl, I can saw my log on Grafana Explorer

image

image

@Garfield550
Copy link
Author

An important thing, I set exitOnError: true in Winston.createLogger.

@chreniuc
Copy link

@Garfield550 did you manage to fix this? I have a similar problem. If I manually send the logs with curl, they show up in grafana, but when winston-loki sends them, they do not show.

@Garfield550
Copy link
Author

@chreniuc Not yet, waiting for solution.

@chreniuc
Copy link

chreniuc commented Nov 23, 2021

@Garfield550 I did an investigation and I managed to fix the problem on my side. I'm not sure if it's the same problem as yours.

I've added logs as you did, I printed the request body that was sent and I also logged here the response.

The request body that send to loki was this:

{"streams":[{"stream":{"level":"info","job":"santier.io-backend"},"values":[["null","POST /item/getAll 200 23ms {\"meta\":{}}"]]}]}

The response from loki was this:

loghttp.PushRequest.Streams: []*loghttp.Stream: unmarshalerDecoder: Value looks like Number/Boolean/None, but can't find its end: ',' or '}' symbol, error found in #10 byte of ...|\":{}}"]]}]}|..., bigger context ...|ull","POST /item/getAll 200 23ms {\"meta\":{}}"]]}]}|...

I've sent the request via curl and I've received the same response:

curl -v -H "Content-Type: application/json" -XPOST -s "http://localhost:3100/loki/api/v1/push" --data-raw   '{"streams":[{"stream":{"level":"info","job":"santier.io-backend"},"values":[["null","POST /item/getAll 200 23ms {\"meta\":{}}"]]}]}'

The fix for me, was to set the replaceTimestamp: true for the LokiTransport. Because the timestamp was being set to null and I think that was a problem for loki.

After setting that to true, the logs showed up in grafana.

@JaniAnttonen shouldn't this be specified in the readme? If that timestamp is set to null, the logs won't show up in grafana, and another thing is that on the loki side, no error is logged for this, I've used debug log for loki and it was only logging this: level=debug ts=2021-11-23T20:00:04.981051386Z caller=logging.go:66 traceID=0964be4b74db8fef msg="POST /loki/api/v1/push (204) 6.888449ms". This makes things harder to investigate.

Or should the library throw an error or something when it receives that response?

I was using loki:2.3.0.

@JaniAnttonen
Copy link
Owner

JaniAnttonen commented Nov 24, 2021

The library should most definitely throw an error if any logs have a null value as a timestamp. Probably even move towards a configuration where there's replaceTimestamp: true by default and if timestamps are found in the received logs and they're valid, they'd be used instead. Great detective work, btw!

@nort3x
Copy link

nort3x commented Jan 26, 2022

i think we are discussing this issue in #90 as well

@JaniAnttonen
Copy link
Owner

@nort3x Yeah, seems to be a duplicate issue. Suggestion: Remove the replaceTimestamp configuration option and use user given timestamps if present, otherwise generate our own. How would that sound?

@nort3x
Copy link

nort3x commented Jan 26, 2022

I'm not experienced but i think the solution should be something that works out of the box and respectful to convention over configuration

@clouedoc
Copy link
Contributor

The problem for me was that I was supplying the host with a trailing slash

E.g. http://example.com/ instead of http://example.com

@Alexsey
Copy link
Contributor

Alexsey commented Jul 29, 2022

The fix #115

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants