diff --git a/geoblock.go b/geoblock.go index 54e65f2..698c307 100755 --- a/geoblock.go +++ b/geoblock.go @@ -277,6 +277,7 @@ func (a *GeoBlock) allowDenyCachedRequestIP(requestIPAddr *net.IP, req *http.Req if !ok { entry, err = a.createNewIPEntry(req, ipAddressString) if err != nil && !(os.IsTimeout(err) && a.ignoreAPITimeout) { + a.infoLogger.Printf("%s: request denied [%s] due to error: %s", a.name, requestIPAddr, err) return false, "" } else if os.IsTimeout(err) && a.ignoreAPITimeout { a.infoLogger.Printf("%s: request allowed [%s] due to API timeout", a.name, requestIPAddr) @@ -295,16 +296,38 @@ func (a *GeoBlock) allowDenyCachedRequestIP(requestIPAddr *net.IP, req *http.Req if time.Since(entry.Timestamp).Hours() >= numberOfHoursInMonth && a.forceMonthlyUpdate { entry, err = a.createNewIPEntry(req, ipAddressString) if err != nil { + a.infoLogger.Printf("%s: request denied [%s] due to error: %s", a.name, requestIPAddr, err) return false, "" } } // check if we are in black/white-list mode and allow/deny based on country code - isAllowed := (stringInSlice(entry.Country, a.countries) != a.blackListMode) || - (entry.Country == unknownCountryCode && a.allowUnknownCountries) + isUnknownCountry := entry.Country == unknownCountryCode + isCountryAllowed := stringInSlice(entry.Country, a.countries) != a.blackListMode + isAllowed := isCountryAllowed || (isUnknownCountry && a.allowUnknownCountries) if !isAllowed { - a.infoLogger.Printf("%s: request denied [%s] for country [%s]", a.name, requestIPAddr, entry.Country) + switch { + case isUnknownCountry && !a.allowUnknownCountries: + a.infoLogger.Printf( + "%s: request denied [%s] for country [%s] due to: unknown country", + a.name, + requestIPAddr, + entry.Country) + case !isCountryAllowed: + a.infoLogger.Printf( + "%s: request denied [%s] for country [%s] due to: country is not allowed", + a.name, + requestIPAddr, + entry.Country) + default: + a.infoLogger.Printf( + "%s: request denied [%s] for country [%s]", + a.name, + requestIPAddr, + entry.Country) + } + return false, entry.Country } @@ -406,13 +429,11 @@ func (a *GeoBlock) getCountryCode(req *http.Request, ipAddressString string) (st return country, nil } - if a.logAPIRequests { - a.infoLogger.Printf( - "%s: Failed to read country from HTTP header field [%s], continuing with API lookup.", - a.name, - a.iPGeolocationHTTPHeaderField, - ) - } + a.infoLogger.Printf( + "%s: Failed to read country from HTTP header field [%s], continuing with API lookup.", + a.name, + a.iPGeolocationHTTPHeaderField, + ) } country, err := a.callGeoJS(ipAddressString) diff --git a/geoblock_test.go b/geoblock_test.go index ad87081..36840d2 100755 --- a/geoblock_test.go +++ b/geoblock_test.go @@ -1177,6 +1177,145 @@ func TestCustomLogFile(t *testing.T) { assertStatusCode(t, recorder.Result(), http.StatusOK) } +func TestLogDeniedDueToHeaderError_FirstCall(t *testing.T) { + apiHandler := &CountryCodeHandler{ResponseCountryCode: "CA"} + + // set up our fake api server + var apiStub = httptest.NewServer(apiHandler) + + tempDir, err := os.MkdirTemp("", "logtest") + if err != nil { + t.Fatalf("Failed to create temporary directory: %v", err) + } + defer os.RemoveAll(tempDir) + + cfg := createTesterConfig() + cfg.API = apiStub.URL + "/{ip}" + cfg.Countries = append(cfg.Countries, "CH") + cfg.IPGeolocationHTTPHeaderField = ipGeolocationHTTPHeaderField + cfg.LogFilePath = tempDir + "/info.log" + cfg.LogAllowedRequests = true + + ctx := context.Background() + next := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {}) + + handler, err := geoblock.New(ctx, next, cfg, "GeoBlock") + if err != nil { + t.Fatal(err) + } + + recorder := httptest.NewRecorder() + + req, err := http.NewRequestWithContext(ctx, http.MethodGet, "http://localhost", nil) + if err != nil { + t.Fatal(err) + } + + req.Header.Add(xForwardedFor, chExampleIP) + req.Header.Set(cfg.IPGeolocationHTTPHeaderField, "C") + + handler.ServeHTTP(recorder, req) + + assertStatusCode(t, recorder.Result(), http.StatusForbidden) + + content, err := os.ReadFile(cfg.LogFilePath) + if err != nil { + t.Fatalf("Failed to read log file: %v", err) + } + + wrongCountryCode := "Failed to read country from HTTP header field [cf-ipcountry], continuing with API lookup" + countryNotAllowed := "request denied [82.220.110.18] for country [CA] due to: country is not allowed" + + if len(content) == 0 || + !strings.Contains(string(content), wrongCountryCode) || + !strings.Contains(string(content), countryNotAllowed) { + t.Fatalf("Empty custom log file or missing expected log lines.") + } +} + +func TestTimeoutOnApiResponse_DenyWhenIgnoreTimeoutFalse(t *testing.T) { + tempDir, err := os.MkdirTemp("", "logtest") + if err != nil { + t.Fatalf("Failed to create temporary directory: %v", err) + } + defer os.RemoveAll(tempDir) + + // Stub server that responds too slowly for our client timeout. + apiStub := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + time.Sleep(50 * time.Millisecond) // > APITimeoutMs below + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("CH")) + })) + defer apiStub.Close() + + cfg := createTesterConfig() + cfg.API = apiStub.URL + "/{ip}" + cfg.Countries = append(cfg.Countries, "CH") + cfg.APITimeoutMs = 5 // 5ms client timeout + cfg.IgnoreAPITimeout = false // timeouts should DENY + cfg.LogFilePath = tempDir + "/info.log" + cfg.LogAllowedRequests = true + + ctx := context.Background() + next := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {}) + + handler, err := geoblock.New(ctx, next, cfg, "GeoBlock") + if err != nil { + t.Fatal(err) + } + + rec := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodGet, "http://localhost", nil) + req.Header.Add(xForwardedFor, chExampleIP) + + handler.ServeHTTP(rec, req) + + assertStatusCode(t, rec.Result(), http.StatusForbidden) + + content, err := os.ReadFile(cfg.LogFilePath) + if err != nil { + t.Fatalf("Failed to read log file: %v", err) + } + + timeoutError := "context deadline exceeded" + + if len(content) == 0 || !strings.Contains(string(content), timeoutError) { + t.Fatalf("Empty custom log file or missing expected log lines.") + } +} + +func TestTimeoutOnApiResponse_AllowWhenIgnoreTimeoutTrue(t *testing.T) { + // Stub server that responds too slowly for our client timeout. + apiStub := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + time.Sleep(50 * time.Millisecond) // > APITimeoutMs below + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte("CH")) + })) + defer apiStub.Close() + + cfg := createTesterConfig() + cfg.API = apiStub.URL + "/{ip}" + cfg.Countries = append(cfg.Countries, "CH") + cfg.APITimeoutMs = 5 // 5ms client timeout + cfg.IgnoreAPITimeout = true // timeouts should ALLOW + + ctx := context.Background() + next := http.HandlerFunc(func(_ http.ResponseWriter, _ *http.Request) {}) + + handler, err := geoblock.New(ctx, next, cfg, "GeoBlock") + if err != nil { + t.Fatal(err) + } + + rec := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodGet, "http://localhost", nil) + req.Header.Add(xForwardedFor, chExampleIP) + + handler.ServeHTTP(rec, req) + + assertStatusCode(t, rec.Result(), http.StatusOK) +} + func assertStatusCode(t *testing.T, req *http.Response, expected int) { t.Helper()