POSTed configuration isn't active

1. The problem I’m having:

Hi - my other assertions in my test are passing, but the test overall is failing because of this failure:

    /Users/daaronch/code/spartacus/caddytest.go:102: failed ensuring config is running: EnsureConfigRunning: POSTed configuration isn't active
    /Users/daaronch/code/spartacus/caddytest.go:126: unable to read the current config

I can’t even figure out where this comes from :frowning: Any suggestions on how to debug?

2. Error messages and/or full log output:


{"level":"info","ts":1715389096.919395,"logger":"http.handlers.spartacus","msg":"Koala config is empty"}
{"level":"info","ts":1715389096.9193962,"logger":"http.handlers.spartacus","msg":"Development mode is disabled"}
{"level":"info","ts":1715389096.9231339,"logger":"pki.ca.local","msg":"root certificate is already trusted by system","path":"storage:pki/authorities/local/root.crt"}
{"level":"info","ts":1715389096.923208,"logger":"http","msg":"enabling HTTP/3 listener","addr":":443"}
{"level":"debug","ts":1715389096.923472,"logger":"http","msg":"starting server loop","address":"[::]:443","tls":true,"http3":true}
{"level":"debug","ts":1715389096.9235132,"logger":"http","msg":"starting server loop","address":"[::]:80","tls":false,"http3":true}
{"level":"info","ts":1715389096.92352,"logger":"http.log","msg":"server running","name":"spartacus_server","protocols":["h1","h2","h3"]}
{"level":"info","ts":1715389096.923538,"logger":"http","msg":"enabling automatic TLS certificate management","domains":["127.0.0.1","localhost"]}
{"level":"warn","ts":1715389096.923753,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [127.0.0.1]: no OCSP server specified in certificate","identifiers":["127.0.0.1"]}
{"level":"debug","ts":1715389096.9237618,"logger":"tls.cache","msg":"added certificate to cache","subjects":["127.0.0.1"],"expiration":1715410164,"managed":true,"issuer_key":"local","hash":"d815544ac6b10fd22d74fbf23b3dd6e27a19058fdf96e96592821e311faf2dfb","cache_size":1,"cache_capacity":10000}
{"level":"debug","ts":1715389096.923771,"logger":"events","msg":"event","name":"cached_managed_cert","id":"4e9163ad-7d2b-452e-bd15-a97a4d96b0f0","origin":"tls","data":{"sans":["127.0.0.1"]}}
{"level":"warn","ts":1715389096.923981,"logger":"tls","msg":"stapling OCSP","error":"no OCSP stapling for [localhost]: no OCSP server specified in certificate","identifiers":["localhost"]}
{"level":"debug","ts":1715389096.923986,"logger":"tls.cache","msg":"added certificate to cache","subjects":["localhost"],"expiration":1715410164,"managed":true,"issuer_key":"local","hash":"934c50b1ce4ec856822a51fa1724d48379de4d47ca00129c72d34f918d81179a","cache_size":2,"cache_capacity":10000}
{"level":"debug","ts":1715389096.9239922,"logger":"events","msg":"event","name":"cached_managed_cert","id":"5e8b605b-5b84-4536-bbe0-88ac0c0968d7","origin":"tls","data":{"sans":["localhost"]}}
{"level":"warn","ts":1715389096.924292,"logger":"tls","msg":"storage cleaning happened too recently; skipping for now","storage":"FileStorage:/Users/daaronch/Library/Application Support/Caddy","instance":"9cfc62d9-28c4-469a-bdd5-97fb30adf0e9","try_again":1715475496.9242911,"try_again_in":86399.999999833}
{"level":"info","ts":1715389096.924354,"msg":"autosaved config (load with --resume flag)","file":"/Users/daaronch/Library/Application Support/Caddy/autosave.json"}
{"level":"info","ts":1715389096.9243588,"logger":"admin.api","msg":"load complete"}
{"level":"info","ts":1715389096.9244869,"msg":"caddytest: config load time took 7.7645ms"}
{"level":"info","ts":1715389096.9245172,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":1715389096.926425,"logger":"admin","msg":"stopped previous server","address":"localhost:2999"}
{"level":"info","ts":1715389106.9449542,"msg":"caddytest: redirecting the dialer from 127.0.0.1:443 to 127.0.0.1:443"}

3. Caddy version:

❯ xcaddy version
v0.4.0 h1:V4n6nNlkRPmrgE+npteBjS7hgMfw24UEmiIONDpIWSo=
❯ ./caddy version
v2.7.6 h1:w0NymbG2m9PcvKWsrXO6EEkY9Ru4FJK8uQbYcev1p3A=

4. How I installed and ran Caddy:

Built caddy with the module.

a. System environment:

MacOS

b. Command:

go test

d. My complete Caddy config:

{
    "logging": {
        "logs": {
            "default": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            },
            "spartacusStdOutLogs": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                },
                "include": [
                    "http.*",
                    "admin.*"
                ]
            },
            "spartacusFileLogs": {
                "level": "DEBUG",
                "writer": {
                    "output": "file",
                    "filename": "/tmp/spartacus.log"
                },
                "include": [
                    "http.*",
                    "admin.*"
                ]
            }
        }
    },
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443",
                        ":80"
                    ],
                    "routes": [
                        {
                            "handle": [
                                {
                                    "handler": "spartacus",
                                    "posthog": {
                                        "Endpoint": "https://iiii.smartmock.io",
                                        "ProjectAPIKey": "phc_REDACT",
                                        "PersonalAPIKey": "phc_REDACT"
                                    },
                                    "development": false
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost",
                                        "127.0.0.1"
                                    ]
                                }
                            ]
                        }
                    ],
                    "logs": {
                        "default_logger_name": "spartacusStdOutLogs",
                        "logger_names": {
                            "localhost": "spartacusStdOutLogs",
                            "127.0.0.1": "spartacusFileLogs"
                        }
                    }
                }
            }
        }
    }
}

5. Links to relevant resources:

I think we’re missing some context. What is the test exactly? What is expected? How can we reproduce the behavior to help troubleshoot?

1 Like

I think the map of logger_names is tripping the checker because maps in Go are randomized. Maybe try flipping the order? That’s one of the pain points in the caddytest package

2 Likes

Interesting! It’s a super generic integration test. I get the same error whether or not I run them all or just run one.


func TestSpartacusIntegration(t *testing.T) {
	ts := caddytest.NewTester(t)

	// Load config from caddy.json
	caddyConfigFileContent, err := os.ReadFile("caddy.json")
	if err != nil {
		t.Fatalf("failed to read caddy.json: %v", err)
	}

	ts.InitServer(string(caddyConfigFileContent), "json")
	ts.Client.Timeout = time.Duration(100 * time.Second)

	baseURL := "https://127.0.0.1"
	contentTypeJSON := "application/json"
	contentTypeText := "text/plain"
	contentTypeBad := "bad"

	tests := []struct {
		name        string
		method      string
		tls         bool
		path        string
		contentType string
		postData    string
		wantStatus  int
		wantBody    string
	}{
		{"https / - ", http.MethodGet, true, "/", "", "", http.StatusOK, "METRICS ENDPOINT"},
		{"http / redirect to https - ", http.MethodGet, false, "/", "", "", http.StatusOK, "METRICS ENDPOINT"},
		{"https / POST empty post - ", http.MethodPost, true, "/", contentTypeJSON, "", http.StatusBadRequest, ""},
		{"https / POST empty json - ", http.MethodPost, true, "/", contentTypeJSON, "{}", http.StatusOK, "OK"},
		{"https / POST empty text - ", http.MethodPost, true, "/", contentTypeText, "{}", http.StatusOK, "OK"},
		{"https / POST bad type - ", http.MethodPost, true, "/", contentTypeBad, "{}", http.StatusOK, "OK"},
	}

	for _, tc := range tests {
		t.Run(tc.name, func(t *testing.T) {
			targetURL, _ := url.JoinPath(baseURL, tc.path)
			bodyReader := bytes.NewReader([]byte(tc.postData))
			req, _ := http.NewRequest(tc.method, targetURL, bodyReader)

			if tc.tls {
				mockTLSConnectionState := new(tls.ConnectionState)
				req.TLS = mockTLSConnectionState
				req.URL.Scheme = "https"
			}

			resp := ts.AssertResponseCode(req, tc.wantStatus)
			body, _ := io.ReadAll(resp.Body)

			if tc.wantBody != "" && !strings.Contains(string(body), tc.wantBody) {
				t.Errorf("got body %q, want %q", string(body), tc.wantBody)
			}
		})
	}
}

BTW, a feature request:

It’d be nice if AssertPutResponseBody could take a substring or a function to check. Not that required, since it passes back the response, but it would be nice.

I don’t mean the test order. I mean the order of items inside the logger_name map.

Top (before) vs. Bottom (after):

$ diff -c --color caddy-before.json caddy-after.json
*** caddy-before.json	Sat May 11 18:33:54 2024
--- caddy-after.json	Sat May 11 18:35:06 2024
***************
*** 66,73 ****
                      "logs": {
                          "default_logger_name": "spartacusStdOutLogs",
                          "logger_names": {
!                             "localhost": "spartacusStdOutLogs",
!                             "127.0.0.1": "spartacusFileLogs"
                          }
                      }
                  }
--- 66,73 ----
                      "logs": {
                          "default_logger_name": "spartacusStdOutLogs",
                          "logger_names": {
!                             "127.0.0.1": "spartacusFileLogs",
!                             "localhost": "spartacusStdOutLogs"
                          }
                      }
                  }

Swapped them both - no change

Alright, just tested it out to see what’s wrong. It’s nothing wrong with your file; just our testing package is currently brittle. We have plans to improve, just haven’t gotten around to it.

Anyways, in your config, you have the logging part at the top. Move it to be below apps.

To illustrate what’s happening, I took your config, replaced the Spartacus specific stuff with static_response just to I can test it out.

Posted config:

{
    "logging": {
        "logs": {
            "default": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            },
            "spartacusStdOutLogs": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                },
                "include": [
                    "http.*",
                    "admin.*"
                ]
            },
            "spartacusFileLogs": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                },
                "include": [
                    "http.*",
                    "admin.*"
                ]
            }
        }
    },
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443",
                        ":80"
                    ],
                    "routes": [
                        {
                            "handle": [
                                {
                                    "handler": "static_response",
                                    "body": "Hello"
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost",
                                        "127.0.0.1"
                                    ]
                                }
                            ]
                        }
                    ],
                    "logs": {
                        "default_logger_name": "spartacusStdOutLogs",
                        "logger_names": {
                            "localhost": "spartacusStdOutLogs",
                            "127.0.0.1": "spartacusFileLogs"
                        }
                    }
                }
            }
        }
    }
}

Active config:

{
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443",
                        ":80"
                    ],
                    "logs": {
                        "default_logger_name": "spartacusStdOutLogs",
                        "logger_names": {
                            "127.0.0.1": "spartacusFileLogs",
                            "localhost": "spartacusStdOutLogs"
                        }
                    },
                    "routes": [
                        {
                            "handle": [
                                {
                                    "body": "Hello",
                                    "handler": "static_response"
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost",
                                        "127.0.0.1"
                                    ]
                                }
                            ]
                        }
                    ]
                }
            }
        }
    },
    "logging": {
        "logs": {
            "default": {
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            },
            "spartacusFileLogs": {
                "include": [
                    "http.*",
                    "admin.*"
                ],
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            },
            "spartacusStdOutLogs": {
                "include": [
                    "http.*",
                    "admin.*"
                ],
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            }
        }
    }
}

The diff is:

*** caddy.json	2024-05-13 16:52:15.207097600 +0300
--- active-config.json	2024-05-13 18:00:22.284399000 +0300
***************
*** 1,34 ****
  {
-     "logging": {
-         "logs": {
-             "default": {
-                 "level": "DEBUG",
-                 "writer": {
-                     "output": "stdout"
-                 }
-             },
-             "spartacusStdOutLogs": {
-                 "level": "DEBUG",
-                 "writer": {
-                     "output": "stdout"
-                 },
-                 "include": [
-                     "http.*",
-                     "admin.*"
-                 ]
-             },
-             "spartacusFileLogs": {
-                 "level": "DEBUG",
-                 "writer": {
-                     "output": "stdout"
-                 },
-                 "include": [
-                     "http.*",
-                     "admin.*"
-                 ]
-             }
-         }
-     },
      "apps": {
          "http": {
              "servers": {
--- 1,4 ----
***************
*** 37,48 ****
                          ":443",
                          ":80"
                      ],
                      "routes": [
                          {
                              "handle": [
                                  {
!                                     "handler": "static_response",
!                                     "body": "Hello"
                                  }
                              ]
                          },
--- 7,25 ----
                          ":443",
                          ":80"
                      ],
+                     "logs": {
+                         "default_logger_name": "spartacusStdOutLogs",
+                         "logger_names": {
+                             "127.0.0.1": "spartacusFileLogs",
+                             "localhost": "spartacusStdOutLogs"
+                         }
+                     },
                      "routes": [
                          {
                              "handle": [
                                  {
!                                     "body": "Hello",
!                                     "handler": "static_response"
                                  }
                              ]
                          },
***************
*** 56,69 ****
                                  }
                              ]
                          }
!                     ],
!                     "logs": {
!                         "default_logger_name": "spartacusStdOutLogs",
!                         "logger_names": {
!                             "localhost": "spartacusStdOutLogs",
!                             "127.0.0.1": "spartacusFileLogs"
!                         }
!                     }
                  }
              }
          }
--- 33,69 ----
                                  }
                              ]
                          }
!                     ]
!                 }
!             }
!         }
!     },
!     "logging": {
!         "logs": {
!             "default": {
!                 "level": "DEBUG",
!                 "writer": {
!                     "output": "stdout"
!                 }
!             },
!             "spartacusFileLogs": {
!                 "include": [
!                     "http.*",
!                     "admin.*"
!                 ],
!                 "level": "DEBUG",
!                 "writer": {
!                     "output": "stdout"
!                 }
!             },
!             "spartacusStdOutLogs": {
!                 "include": [
!                     "http.*",
!                     "admin.*"
!                 ],
!                 "level": "DEBUG",
!                 "writer": {
!                     "output": "stdout"
                  }
              }
          }

At a glance, the retrieved (active) config appears to have the keys in sorted order. You might have to play around with it to get it right.

Again, we’re trying to improve the caddytest package; it’s hard :slightly_smiling_face:

2 Likes

As a workaround for now, you can probably json.Unmarshal then json.Marshal your loaded JSON config, because Go’s marshal will sort keys automatically. That way you can do your comparisons more confidently.

I think it would make sense for the Caddy testing helpers to do that for you, but as a workaround you can do it in your own test for now.

1 Like

We’re normalizing the JSON in InitServer now. This change will go out with v2.8.0

1 Like

sounds awesome - i can easily wait until 2.8.0 to solve this :slight_smile:

I hate to bug - and really appreciate everyone’s help so far, but i still seem to be running into it:

❯ ./caddy version
4c90f1427f22a85f767dbeabb3bedcc8f9355c84+modified (14 May 24 07:50 UTC)

Here’s my minimal caddy config (which i THINK is the same as yours?):

{
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443",
                        ":80"
                    ],
                    "logs": {
                        "default_logger_name": "spartacusStdOutLogs",
                        "logger_names": {
                            "127.0.0.1": "spartacusFileLogs",
                            "localhost": "spartacusStdOutLogs"
                        }
                    },
                    "routes": [
                        {
                            "handle": [
                                {
                                    "body": "Hello",
                                    "handler": "static_response"
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost",
                                        "127.0.0.1"
                                    ]
                                }
                            ]
                        }
                    ]
                }
            }
        }
    },
    "logging": {
        "logs": {
            "spartacusFileLogs": {
                "include": [
                    "http.*",
                    "admin.*"
                ],
                "level": "DEBUG",
                "writer": {
                    "filename": "/tmp/access-foo.json",
                    "output": "file"
                }
            },
            "spartacusStdOutLogs": {
                "include": [
                    "http.*",
                    "admin.*"
                ],
                "level": "DEBUG",
                "writer": {
                    "output": "stdout"
                }
            }
        }
    }
}

Here’s tmp:

> ls /tmp/access*
zsh: no matches found: /tmp/access*

Here’s stdout (note the

2024/05/14 16:54:57.551	INFO	serving initial configuration
2024/05/14 16:56:30.289	INFO	http.log.access.loopback	NOP	{"request": {"remote_ip": "127.0.0.1", "remote_port": "60414", "client_ip": "127.0.0.1", "proto": "HTTP/1.1", "method": "GET", "host": "127.0.0.1", "uri": "/", "headers": {"User-Agent": ["curl/8.4.0"], "Accept": ["*/*"]}}, "bytes_read": 0, "user_id": "", "duration": 0.000002708, "size": 0, "status": 0, "resp_headers": {"Server": ["Caddy"], "Alt-Svc": ["h3=\":443\"; ma=2592000"]}}
^C2024/05/14 16:56:50.274	INFO	shutting down	{"signal": "SIGINT"}
2024/05/14 16:56:50.274	WARN	exiting; byeee!! 👋	{"signal": "SIGINT"}
2024/05/14 16:56:50.274	INFO	http	servers shutting down with eternal grace period
2024/05/14 16:56:50.274	INFO	admin	stopped previous server	{"address": "localhost:2019"}
2024/05/14 16:56:50.274	INFO	shutdown complete	{"signal": "SIGINT", "exit_code": 0}

Ok, FWIW, here’s what i got to work with minimal repro:

WORKS (BTW, this is the output of caddy adapt with logging at the top)

{
    "logging": {
        "logs": {
            "default": {
                "exclude": [
                    "http.log.access.filelog"
                ]
            },
            "filelog": {
                "writer": {
                    "filename": "access-foo.json",
                    "output": "file"
                },
                "include": [
                    "http.log.access.filelog"
                ]
            }
        }
    },
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443"
                    ],
                    "routes": [
                        {
                            "handle": [
                                {
                                    "body": "Hello",
                                    "handler": "static_response"
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost"
                                    ]
                                }
                            ]
                        }
                    ],
                    "logs": {
                        "logger_names": {
                            "localhost": "filelog"  // HERE----------------
                        }
                    }
                }
            }
        }
    }
}

Prints to STDOUT:

{
    "logging": {
        "logs": {
            "default": {
                "exclude": [
                    "http.log.access.filelog"
                ]
            },
            "filelog": {
                "writer": {
                    "filename": "access-foo.json",
                    "output": "file"
                },
                "include": [
                    "http.log.access.filelog"
                ]
            }
        }
    },
    "apps": {
        "http": {
            "servers": {
                "spartacus_server": {
                    "listen": [
                        ":443"
                    ],
                    "routes": [
                        {
                            "handle": [
                                {
                                    "body": "Hello",
                                    "handler": "static_response"
                                }
                            ]
                        },
                        {
                            "match": [
                                {
                                    "host": [
                                        "localhost"
                                    ]
                                }
                            ]
                        }
                    ],
                    "logs": {
                        "logger_names": {
                            "spartacus_server": "filelog" // HERE----------------
                        }
                    }
                }
            }
        }
    }
}

This seems super non-intuitive - unless i misread, the log is associated with the domain name, not the server name?

Yes, logger_names maps hostnames to a logger name (one or more logger names in v2.8.0, you can provide an array instead of a string in the logger_names map).

3 Likes