PREMESSA

Stamani stavo spulciando i log di alcuni siti internet per verificare che il passaggio al nuovo server/IP fosse corretto: ad un certo punto trovo nel log una sezione simile a questa:

#Software: Microsoft Internet Information Services 6.0
#Version: 1.0
#Date: 2007-08-29 00:23:48

#Fields: date time s-sitename s-ip cs-method cs-uri-stem 
2007-08-29 00:23:48 W3SVC824241 xx.xx.xx.xx GET /img/xxx.jpg 
2007-08-29 00:37:15 W3SVC824241 xx.xx.xx.xx HEAD /Default.asp
#Software: Microsoft Internet Information Services 6.0

#Version: 1.0
#Date: 2007-08-29 04:27:34
#Fields: date time s-sitename s-ip cs-method cs-uri-stem
 
2007-08-29 04:27:34 W3SVC824241 xx.xx.xx.xx GET /robots.txt
2007-08-29 04:27:37 W3SVC824241 xx.xx.xx.xx GET /XXX.asp

#Software: Microsoft Internet Information Services 6.0
#Version: 1.0
#Date: 2007-08-29 05:09:00
#Fields: date time s-sitename s-ip cs-method
 
2007-08-29 05:09:00 W3SVC824241 xx.xx.xx.xx GET /XXX.asp 
2007-08-29 05:24:08 W3SVC824241 xx.xx.xx.xx GET /XXX.pdf 
2007-08-29 05:31:43 W3SVC824241 xx.xx.xx.xx GET /Default.asp 
#Software: Microsoft Internet Information Services 6.0

#Version: 1.0
#Date: 2007-08-29 06:47:39
#Fields: date time s-sitename s-ip cs-method 
2007-08-29 06:47:39 W3SVC824241 v GET /Default.asp

In grassetto ho evidenziato la parte che mi ha lasciato perplesso: perchè l'header del log viene scritto più volte quando, in passato, veniva scritto solo all'apertura del file (oppure dopo ogni riavvio/crash di IIS  )?

La prima cosa che ho pensato è che il mio nuovo "ferro" (aka web server) avesse dei problemi che lo facevano crashare continuamente (e dato che i siti sono dinamici e che io non mi fido dei programmatori, la cosa era anche plausibile!). Peccato però che lo stesso comportamento era presente anche sulla macchina vecchia.

 

SPIEGAZIONE

Girellando sul sito Microsoft ho trovato un articolo che riguarda appunto la parte di logging di IIS 6.0 , i cui punti salienti sono:

  • La funzione di logging è stata spostata dal modulo w3svc (il processo "principale" di IIS) al modulo HTTP.sys (nuovo oggetto introdotto in IIS6 - fonte anche lui di casini, vedi la gestione del socket pooling!)
  • Per questo motivo adesso è possibile loggare in UTF-8 (saranno contenti gli asiatici!) e anche in binario 
  • L'header viene scritto nel file di log ogni volta che quest'ultimo viene aperto
  • http.sys ha un timeout di 15 minuti: questo significa che se non riceve dal sito web corrispondente dati da loggare entro 15 minuti, chiude il log.
Quindi, se il sito non è molto "trafficato" accade che IIS (pardon HTTP.sys) apre il log, scrive l'header, scrive la richiesta, aspetta 15 minuti e, non avendo ricevuto altro, chiude il log. Alla successiva richiesta (magari dopo 30 minuti) la sequenza si ripete...

 

NOTA DI COLORE (poteva mancare???)

L'articolo Microsoft inizia così:

Historically, IIS administrators have rarely had to troubleshoot logging problems. In earlier versions of IIS, log configuration was simple and straightforward, and in most cases, the default settings were adequate.

In IIS 6.0, new logging functionality, [... CUT ...] present new configuration options and architectural elements as well as new troubleshooting challenges. 

 

Che, tradotto, significa (almeno secondo me): "Nelle versioni precedenti funzionava tutto come un orologio, ma da ora in poi potrebbe non essere più così a causa delle nuove funzioni introdotte" (che lo facciano per "pararsi il culo" come si dice dalle mie parti?)

Non aggiungo altro se non che mi sono venute in mente due frasi famose alla fine di questo articolo:

  • tutto quello che non c'è non si guasta
  • Le cose semplici sono sempre quelle che funzionano meglio (motivo per cui io uso quasi sempre il log su file!)