Log configuration is ignored

[imyelo]

Your Environment

• verdaccio version: 5.21.1
• node version: v18.14.0 (actually using docker image
• package manager: npm@9.3.1
• os: linux
• platform: docker, helm

Describe the bug

I configured the log part in the config.yaml file expecting the log to be output to a file, but it is actually outputting to stdout anyway.
I'm using Verdaccio in K8s and the rest of the configuration is just working fine, e.g. web.title, so I can confirm that it is not a mounting issue.

To Reproduce

Deploy using the verdaccio:5.21.1 image and configure the log part as I did in the configuration file below.

Expected behavior

log to /verdaccio/logs/pino.log

Screenshots, server logs, package manager log

2023-04-12T12:08:44.593Z verdaccio:logger logging stdout enabled                                              
2023-04-12T12:08:44.595Z verdaccio:logger setup logger                                                        
2023-04-12T12:08:44.595Z verdaccio:logger has prettifier? true                                                
2023-04-12T12:08:52.097Z verdaccio:plugin:local-storage sync database started                                 
2023-04-12T12:08:52.098Z verdaccio:plugin:local-storage sync folder '/verdaccio/storage/data' created succee  
2023-04-12T12:08:52.098Z verdaccio:plugin:local-storage sync write succeed                                    
2023-04-12T12:08:52.100Z verdaccio:plugin:local-storage sync database started                                 
2023-04-12T12:08:52.100Z verdaccio:plugin:local-storage sync folder '/verdaccio/storage/data' created succee  
2023-04-12T12:08:52.100Z verdaccio:plugin:local-storage sync write succeed                                    
2023-04-12T12:08:52.101Z verdaccio:plugin:loader isScoped false                                               
2023-04-12T12:08:52.101Z verdaccio:plugin:loader loading plugin /usr/local/lib/node_modules/verdaccio/build/  
2023-04-12T12:08:52.185Z verdaccio:plugin:loader plugin /usr/local/lib/node_modules/verdaccio/build/plugins/  
2023-04-12T12:08:52.186Z verdaccio:plugin:loader loading plugin verdaccio-htpasswd                            
2023-04-12T12:08:52.194Z verdaccio:plugin:loader plugin htpasswd is an npm package                            
2023-04-12T12:08:52.194Z verdaccio:plugin:loader plugin is ES6                                                
2023-04-12T12:08:52.197Z verdaccio:plugin:loader isScoped false                                               
2023-04-12T12:08:52.197Z verdaccio:plugin:loader loading plugin /usr/local/lib/node_modules/verdaccio/build/  
2023-04-12T12:08:52.198Z verdaccio:plugin:loader plugin /usr/local/lib/node_modules/verdaccio/build/plugins/  
2023-04-12T12:08:52.198Z verdaccio:plugin:loader loading plugin verdaccio-audit                               
2023-04-12T12:08:52.593Z verdaccio:plugin:loader plugin audit is an npm package                               
2023-04-12T12:08:52.593Z verdaccio:plugin:loader plugin is ES6                                                
2023-04-12T12:08:52.690Z verdaccio:plugin:local-storage get full list of packages (0) has been fetched        
2023-04-12T12:08:52.696Z verdaccio:web:render static path '/usr/local/lib/node_modules/verdaccio/node_module  
2023-04-12T12:08:53.073Z verdaccio:logger http (25) was changed to http (25)                                  
2023-04-12T12:08:53.081Z verdaccio:logger http (25) was changed to http (25)                                  
warn --- config file  - /verdaccio/conf/config.yaml                                                           
info --- plugin successfully loaded: verdaccio-htpasswd                                                       
info --- plugin successfully loaded: verdaccio-audit                                                          
warn --- http address - http://0.0.0.0:4873/ - verdaccio/5.21.1                                               
info <-- 10.244.0.1 requested 'GET /-/ping'                                                                   
http <-- 200, user: null(10.244.0.1), req: 'GET /-/ping', bytes: 0/0                                          
info <-- 10.244.0.1 requested 'GET /-/ping'                                                                   
http <-- 200, user: null(10.244.0.1), req: 'GET /-/ping', bytes: 0/0                                          
http <-- 200, user: null(10.244.0.1), req: 'GET /-/ping', bytes: 0/3                                          
http <-- 200, user: null(10.244.0.1), req: 'GET /-/ping', bytes: 0/3     

From the logs, it appears that the logger is initialized before the configuration file is read, which may be the key.

Configuration File (cat ~/.config/verdaccio/config.yaml)

deployment.yaml:

apiVersion: apps/v1
kind: Deployment
metadata:
  name: npm
  namespace: default
  labels:
    app: verdaccio
spec:
  selector:
    matchLabels:
      app: verdaccio
  template:
    metadata:
      labels:
        app: verdaccio
    spec:
      containers:
        - env:
            - name: DEBUG
              value: verdaccio:*
          image: verdaccio/verdaccio:5.21.1
          imagePullPolicy: IfNotPresent
          livenessProbe:
            httpGet:
              path: /-/ping
              port: 4873
              scheme: HTTP
            initialDelaySeconds: 5
          name: verdaccio
          ports:
            - containerPort: 4873
              name: tcp-4873
              protocol: TCP
          readinessProbe:
            httpGet:
              path: /-/ping
              port: 4873
              scheme: HTTP
            initialDelaySeconds: 5
          resources:
            limits:
              cpu: 200m
              memory: 256Mi
            requests:
              cpu: 100m
              memory: 128Mi
          securityContext:
            runAsUser: 10001
          volumeMounts:
            - mountPath: /verdaccio/storage
              name: persistence
            - mountPath: /verdaccio/conf/config.yaml
              name: configmap-verdaccio-config
              readOnly: true
              subPath: config.yaml
            - mountPath: /verdaccio/storage/htpasswd
              name: configmap-verdaccio-htpasswd
              readOnly: true
              subPath: htpasswd
            - mountPath: /verdaccio/logs
              name: log
      securityContext:
        fsGroup: 101
      volumes:
        - name: persistence
          persistentVolumeClaim:
            claimName: verdaccio
        - configMap:
            defaultMode: 420
            items:
              - key: config.yaml
                path: config.yaml
            name: verdaccio-config
          name: configmap-verdaccio-config
        - configMap:
            defaultMode: 420
            items:
              - key: htpasswd
                path: htpasswd
            name: verdaccio-htpasswd
          name: configmap-verdaccio-htpasswd
        - hostPath:
            path: /tmp/logs
          name: log

config.yaml:

# config.yaml
storage: /verdaccio/storage/data
web:
  title: NPM
auth:
  htpasswd:
    file: /verdaccio/storage/htpasswd
    max_users: -1
    algorithm: bcrypt
uplinks:
  npmjs:
    url: https://registry.npmjs.org/
    agent_options:
      keepAlive: true
      maxSockets: 40
      maxFreeSockets: 10
packages:
  '@foobar/*':
    # scoped packages
    access: $authenticated
    publish: $authenticated
  '**':
    access: $all
    publish: $authenticated
    proxy: npmjs
middlewares:
  audit:
    enabled: true
log:
  type: file
  path: /verdaccio/logs/pino.log
  level: info

Environment information

Environment Info:
  System:
    OS: Linux 5.19 Alpine Linux
    CPU: (6) x64 Intel(R) Core(TM) i5-9400 CPU @ 2.90GHz
  Binaries:
    npm: 9.3.1 - /usr/local/bin/npm
  npmGlobalPackages:
    verdaccio: 5.21.1

uplinks)

• $ DEBUG=verdaccio* verdaccio enable extreme verdaccio debug mode (verdaccio api)
• $ npm -ddd prints:
• $ npm config get registry prints:
  -->

Contribute to Verdaccio

• I'm willing to fix this bug 🥇

[juanpicado]

It was fixed here https://github.com/verdaccio/verdaccio/releases/tag/v5.22.1 try out

[thekevinscott]

I'm still seeing logs printed to stdout.

I'm using the Config Builder API​ and doing something like:

    .addLogger({ level: 'info', type: 'file', format: 'file' })

It still prints to stdout. Also, the typescript definitions forbid me from specifying a file property in the JSON.

[juanpicado]

I'm still seeing logs printed to stdout.

Do you use Node_env === production ? Because is intended, Pino.js disable JSON prettify in production because is costly in resources. Prettify is cool for local development and low workload, for servers, never use prettify.

the typescript definitions forbid me from specifying a file property in the JSON.

I'll double check that part, might be TS issue I did.

[thekevinscott]

It appears that in both cases, any .addLogger({ ... }) command is ignored.

For NODE_ENV=production I see logs in the format:

{"level":30,"time":1693307303572,"pid":1234,"hostname":"hostname","packageName":"packageName","msg":"undefined is allowed publish for foo"}

I see levels 25 and 30 in the logs.

For non-production (i.e., if I omit the NODE_ENV=production), I see what I believe are the prettified logs:

 info <-- ::ffff:127.0.0.1 requested 'PUT /foo'
 info --- auth/allow_action: access granted to: undefined
 info --- undefined is allowed publish for foo

So there's definitely a difference in output between the two environments, but in both cases anything I enter for addLogger is ignored.

[juanpicado]

could you share which versions ? of each library

[thekevinscott]

Node: v16.20.2
"verdaccio": "^5.26.1"
"@verdaccio/types": "^10.8.0"

[juanpicado]

"@verdaccio/types": "^10.8.0" definitely types are old, please use https://github.com/verdaccio/verdaccio/blob/5.x/package.json#L103 the same as the 5.x repo

Sorry the confusion :) is hard to keep improving new versions without break old ones.

[thekevinscott]

It's all good, your efforts are very much appreciated! Hopefully my comments help make verdaccio even better!

I think there's two separate issues, would it be helpful to make new bug reports for them separately?

1. The typings mismatch
2. The logging-to-stdout / ignoring addLogger issue

Regarding the typing issue, I've upgraded to 12.0.0-next.0.

addLogger appears to accept a LoggerConfItem which is I believe defined here and does not have a path parameter:

export interface LoggerConfItem {
  type: LoggerType;
  format: LoggerFormat;
  level: LoggerLevel;
}

However, I do see LoggerConfigItem up above which does appear to have a path parameter:

export type LoggerConfigItem = {
  type?: LoggerType;
  format?: LoggerFormat;
  path?: string;
  level?: string;
  colors?: boolean;
  async?: boolean;
};

But I don't believe LoggerConfigItem is a valid argument for addLogger. I'd also note that level is defined in LoggerConfItem as being of type LoggerLevel whereas in LoggerConfigItem it is defined as a string, which I believe is invalid (unless I am misinterpreting the purpose of the type definitions).

[juanpicado]

Thank u for the detailed feedback, I'll take notes, since I've been touching logging recently and I will release soon v6 will check this works properly before do it (besides other bugs are around 😅).

[thekevinscott]

Thanks! Let me know if I can provide any more assistance.

[ispringer]

I'm also seeing the log config being ignored and all logging going to stdout after upgrading to verdaccio 5.29.2.

My environment:

$ uname -a
Linux e1npm1 4.14.171-105.231.amzn1.x86_64 #1 SMP Thu Feb 27 23:49:15 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ node --version
v16.20.2
$ npm --version
8.19.4
$ verdaccio --version
v5.29.2

and my config file contains:

log:
  - { type: file, path: /opt/evergage/verdaccio/verdaccio.log, level: trace, format: pretty-timestamped }

[pward123]

I also tried 5.22.1, setting log level to trace directly in the config file results in no logging at all

[pward123]

Looks like running in production mode and removing pretty { type: stdout, level: trace } seems to get me some logging