python-doc-tw.github.io/howto/logging-cookbook.html at master · python-doc-tw/python-doc-tw.github.io

History

2584 lines (2420 loc) · 294 KB

Raw

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125

126

127

128

129

130

131

132

133

134

135

136

137

138

139

140

141

142

143

144

145

146

147

148

149

150

151

152

153

154

155

156

157

158

159

160

161

162

163

164

165

166

167

168

169

170

171

172

173

174

175

176

177

178

179

180

181

182

183

184

185

186

187

188

189

190

191

192

193

194

195

196

197

198

199

200

201

202

203

204

205

206

207

208

209

210

211

212

213

214

215

216

217

218

219

220

221

222

223

224

225

226

227

228

229

230

231

232

233

234

235

236

237

238

239

240

241

242

243

244

245

246

247

248

249

250

251

252

253

254

255

256

257

258

259

260

261

262

263

264

265

266

267

268

269

270

271

272

273

274

275

276

277

278

279

280

281

282

283

284

285

286

287

288

289

290

291

292

293

294

295

296

297

298

299

300

301

302

303

304

305

306

307

308

309

310

311

312

313

314

315

316

317

318

319

320

321

322

323

324

325

326

327

328

329

330

331

332

333

334

335

336

337

338

339

340

341

342

343

344

345

346

347

348

349

350

351

352

353

354

355

356

357

358

359

360

361

362

363

364

365

366

367

368

369

370

371

372

373

374

375

376

377

378

379

380

381

382

383

384

385

386

387

388

389

390

391

392

393

394

395

396

397

398

399

400

401

402

403

404

405

406

407

408

409

410

411

412

413

414

415

416

417

418

419

420

421

422

423

424

425

426

427

428

429

430

431

432

433

434

435

436

437

438

439

440

441

442

443

444

445

446

447

448

449

450

451

452

453

454

455

456

457

458

459

460

461

462

463

464

465

466

467

468

469

470

471

472

473

474

475

476

477

478

479

480

481

482

483

484

485

486

487

488

489

490

491

492

493

494

495

496

497

498

499

500

501

502

503

504

505

506

507

508

509

510

511

512

513

514

515

516

517

518

519

520

521

522

523

524

525

526

527

528

529

530

531

532

533

534

535

536

537

538

539

540

541

542

543

544

545

546

547

548

549

550

551

552

553

554

555

556

557

558

559

560

561

562

563

564

565

566

567

568

569

570

571

572

573

574

575

576

577

578

579

580

581

582

583

584

585

586

587

588

589

590

591

592

593

594

595

596

597

598

599

600

601

602

603

604

605

606

607

608

609

610

611

612

613

614

615

616

617

618

619

620

621

622

623

624

625

626

627

628

629

630

631

632

633

634

635

636

637

638

639

640

641

642

643

644

645

646

647

648

649

650

651

652

653

654

655

656

657

658

659

660

661

662

663

664

665

666

667

668

669

670

671

672

673

674

675

676

677

678

679

680

681

682

683

684

685

686

687

688

689

690

691

692

693

694

695

696

697

698

699

700

701

702

703

704

705

706

707

708

709

710

711

712

713

714

715

716

717

718

719

720

721

722

723

724

725

726

727

728

729

730

731

732

733

734

735

736

737

738

739

740

741

742

743

744

745

746

747

748

749

750

751

752

753

754

755

756

757

758

759

760

761

762

763

764

765

766

767

768

769

770

771

772

773

774

775

776

777

778

779

780

781

782

783

784

785

786

787

788

789

790

791

792

793

794

795

796

797

798

799

800

801

802

803

804

805

806

807

808

809

810

811

812

813

814

815

816

817

818

819

820

821

822

823

824

825

826

827

828

829

830

831

832

833

834

835

836

837

838

839

840

841

842

843

844

845

846

847

848

849

850

851

852

853

854

855

856

857

858

859

860

861

862

863

864

865

866

867

868

869

870

871

872

873

874

875

876

877

878

879

880

881

882

883

884

885

886

887

888

889

890

891

892

893

894

895

896

897

898

899

900

901

902

903

904

905

906

907

908

909

910

911

912

913

914

915

916

917

918

919

920

921

922

923

924

925

926

927

928

929

930

931

932

933

934

935

936

937

938

939

940

941

942

943

944

945

946

947

948

949

950

951

952

953

954

955

956

957

958

959

960

961

962

963

964

965

966

967

968

969

970

971

972

973

974

975

976

977

978

979

980

981

982

983

984

985

986

987

988

989

990

991

992

993

994

995

996

997

998

999

1000

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"

"http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<head>

<title>Logging Cookbook — Python 3.7.0 說明文件</title>

title="在 Python 3.7.0 說明文件中搜尋"

href="../_static/opensearch.xml"/>

</head><body>

<ul>

<a href="../genindex.html" title="General Index"

accesskey="I">索引</a></li>

<a href="../py-modindex.html" title="Python 模組索引"

>模組</a> |</li>

<a href="regex.html" title="如何使用正規表達式"

accesskey="N">下一頁</a> |</li>

<a href="logging.html" title="如何使用 Logging 模組"

accesskey="P">上一頁</a> |</li>

<li><img src="../_static/py.png" alt=""

style="vertical-align: middle; margin-top: -1px"/></li>

<li><a href="https://www.python.org/">Python</a> »</li>

<li>

zh_TW

3.7.0

<a href="../index.html">Documentation </a> »

</li>

<li class="nav-item nav-item-1"><a href="index.html" accesskey="U">Python HOWTOs</a> »</li>

</form>

</div>

</li>

</ul>

</div>

<h1>Logging Cookbook<a class="headerlink" href="#logging-cookbook" title="本標題的永久連結">¶</a></h1>

<tr class="field-odd field"><th class="field-name">Author:</th><td class="field-body">原文作者 Vinay Sajip <vinay_sajip at red-dove dot com></td>

</tr>

</tbody>

</table>

This page contains a number of recipes related to logging, which have been found

useful in the past.

<h2>Using logging in multiple modules<a class="headerlink" href="#using-logging-in-multiple-modules" title="本標題的永久連結">¶</a></h2>

Multiple calls to <code class="docutils literal notranslate">logging.getLogger('someLogger')</code> return a reference to the

same logger object. This is true not only within the same module, but also

across modules as long as it is in the same Python interpreter process. It is

true for references to the same object; additionally, application code can

define and configure a parent logger in one module and create (but not

configure) a child logger in a separate module, and all logger calls to the

child will pass up to the parent. Here is a main module:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

import auxiliary_module

# create logger with 'spam_application'

logger = logging.getLogger('spam_application')

logger.setLevel(logging.DEBUG)

# create file handler which logs even debug messages

fh = logging.FileHandler('spam.log')

fh.setLevel(logging.DEBUG)

# create console handler with a higher log level

ch = logging.StreamHandler()

ch.setLevel(logging.ERROR)

# create formatter and add it to the handlers

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

fh.setFormatter(formatter)

ch.setFormatter(formatter)

# add the handlers to the logger

logger.addHandler(fh)

logger.addHandler(ch)

logger.info('creating an instance of auxiliary_module.Auxiliary')

a = auxiliary_module.Auxiliary()

logger.info('created an instance of auxiliary_module.Auxiliary')

logger.info('calling auxiliary_module.Auxiliary.do_something')

a.do_something()

logger.info('finished auxiliary_module.Auxiliary.do_something')

logger.info('calling auxiliary_module.some_function()')

auxiliary_module.some_function()

logger.info('done with auxiliary_module.some_function()')

</pre></div>

</div>

Here is the auxiliary module:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

# create logger

module_logger = logging.getLogger('spam_application.auxiliary')

class Auxiliary:

def __init__(self):

self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')

self.logger.info('creating an instance of Auxiliary')

def do_something(self):

a = 1 + 1

self.logger.info('done doing something')

def some_function():

module_logger.info('received a call to "some_function"')

</pre></div>

</div>

The output looks like this:

<div class="highlight-none notranslate"><div class="highlight"><pre>2005-03-23 23:47:11,663 - spam_application - INFO -

creating an instance of auxiliary_module.Auxiliary

2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -

creating an instance of Auxiliary

2005-03-23 23:47:11,665 - spam_application - INFO -

created an instance of auxiliary_module.Auxiliary

2005-03-23 23:47:11,668 - spam_application - INFO -

calling auxiliary_module.Auxiliary.do_something

2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -

doing something

2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -

done doing something

2005-03-23 23:47:11,670 - spam_application - INFO -

finished auxiliary_module.Auxiliary.do_something

2005-03-23 23:47:11,671 - spam_application - INFO -

calling auxiliary_module.some_function()

2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -

received a call to 'some_function'

2005-03-23 23:47:11,673 - spam_application - INFO -

done with auxiliary_module.some_function()

</pre></div>

</div>

<h2>Logging from multiple threads<a class="headerlink" href="#logging-from-multiple-threads" title="本標題的永久連結">¶</a></h2>

Logging from multiple threads requires no special effort. The following example

shows logging from the main (initial) thread and another thread:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

import threading

import time

def worker(arg):

while not arg['stop']:

logging.debug('Hi from myfunc')

time.sleep(0.5)

def main():

logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')

info = {'stop': False}

thread = threading.Thread(target=worker, args=(info,))

thread.start()

while True:

try:

logging.debug('Hello from main')

time.sleep(0.75)

except KeyboardInterrupt:

info['stop'] = True

break

thread.join()

if __name__ == '__main__':

main()

</pre></div>

</div>

When run, the script should print something like the following:

<div class="highlight-none notranslate"><div class="highlight"><pre> 0 Thread-1 Hi from myfunc

3 MainThread Hello from main

505 Thread-1 Hi from myfunc

755 MainThread Hello from main

1007 Thread-1 Hi from myfunc

1507 MainThread Hello from main

1508 Thread-1 Hi from myfunc

2010 Thread-1 Hi from myfunc

2258 MainThread Hello from main

2512 Thread-1 Hi from myfunc

3009 MainThread Hello from main

3013 Thread-1 Hi from myfunc

3515 Thread-1 Hi from myfunc

3761 MainThread Hello from main

4017 Thread-1 Hi from myfunc

4513 MainThread Hello from main

4518 Thread-1 Hi from myfunc

</pre></div>

</div>

This shows the logging output interspersed as one might expect. This approach

works for more threads than shown here, of course.

</div>

<h2>Multiple handlers and formatters<a class="headerlink" href="#multiple-handlers-and-formatters" title="本標題的永久連結">¶</a></h2>

Loggers are plain Python objects. The <a class="reference internal" href="../library/logging.html#logging.Logger.addHandler" title="logging.Logger.addHandler"><code class="xref py py-meth docutils literal notranslate">addHandler()</code></a> method has no

minimum or maximum quota for the number of handlers you may add. Sometimes it

will be beneficial for an application to log all messages of all severities to a

text file while simultaneously logging errors or above to the console. To set

this up, simply configure the appropriate handlers. The logging calls in the

application code will remain unchanged. Here is a slight modification to the

previous simple module-based configuration example:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

# create file handler which logs even debug messages

# create console handler with a higher log level

ch = logging.StreamHandler()

# create formatter and add it to the handlers

ch.setFormatter(formatter)

fh.setFormatter(formatter)

# add the handlers to logger

logger.addHandler(ch)

logger.addHandler(fh)

# 'application' code

logger.debug('debug message')

logger.info('info message')

logger.warn('warn message')

logger.error('error message')

logger.critical('critical message')

</pre></div>

</div>

Notice that the 『application』 code does not care about multiple handlers. All

that changed was the addition and configuration of a new handler named fh.

The ability to create new handlers with higher- or lower-severity filters can be

very helpful when writing and testing an application. Instead of using many

<code class="docutils literal notranslate">print</code> statements for debugging, use <code class="docutils literal notranslate">logger.debug</code>: Unlike the print

statements, which you will have to delete or comment out later, the logger.debug

statements can remain intact in the source code and remain dormant until you

need them again. At that time, the only change that needs to happen is to

modify the severity level of the logger and/or handler to debug.

</div>

<h2>Logging to multiple destinations<a class="headerlink" href="#logging-to-multiple-destinations" title="本標題的永久連結">¶</a></h2>

Let’s say you want to log to console and file with different message formats and

in differing circumstances. Say you want to log messages with levels of DEBUG

and higher to file, and those messages at level INFO and higher to the console.

Let’s also assume that the file should contain timestamps, but the console

messages should not. Here’s how you can achieve this:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

# set up logging to file - see previous section for more details

format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',

datefmt='%m-%d %H:%M',

filename='/temp/myapp.log',

filemode='w')

# define a Handler which writes INFO messages or higher to the sys.stderr

console = logging.StreamHandler()

console.setLevel(logging.INFO)

# set a format which is simpler for console use

formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')

# tell the handler to use this format

console.setFormatter(formatter)

# add the handler to the root logger

logging.getLogger('').addHandler(console)

# Now, we can log to the root logger, or any other logger. First the root...

logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your

# application:

logger1 = logging.getLogger('myapp.area1')

logger2 = logging.getLogger('myapp.area2')

logger1.debug('Quick zephyrs blow, vexing daft Jim.')

logger1.info('How quickly daft jumping zebras vex.')

logger2.warning('Jail zesty vixen who grabbed pay from quack.')

logger2.error('The five boxing wizards jump quickly.')

</pre></div>

</div>

When you run this, on the console you will see

<div class="highlight-none notranslate"><div class="highlight"><pre>root : INFO Jackdaws love my big sphinx of quartz.

myapp.area1 : INFO How quickly daft jumping zebras vex.

myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack.

myapp.area2 : ERROR The five boxing wizards jump quickly.

</pre></div>

</div>

and in the file you will see something like

<div class="highlight-none notranslate"><div class="highlight"><pre>10-22 22:19 root INFO Jackdaws love my big sphinx of quartz.

10-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.

10-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex.

10-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.

10-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly.

</pre></div>

</div>

As you can see, the DEBUG message only shows up in the file. The other messages

are sent to both destinations.

This example uses console and file handlers, but you can use any number and

combination of handlers you choose.

</div>

<h2>Configuration server example<a class="headerlink" href="#configuration-server-example" title="本標題的永久連結">¶</a></h2>

Here is an example of a module using the logging configuration server:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

import logging.config

import time

import os

# read initial config file

logging.config.fileConfig('logging.conf')

# create and start listener on port 9999

t = logging.config.listen(9999)

t.start()

try:

# loop through logging calls to see the difference

# new configurations make, until Ctrl+C is pressed

while True:

logger.debug('debug message')

logger.info('info message')

logger.warn('warn message')

logger.error('error message')

logger.critical('critical message')

time.sleep(5)

except KeyboardInterrupt:

# cleanup

logging.config.stopListening()

t.join()

</pre></div>

</div>

And here is a script that takes a filename and sends that file to the server,

properly preceded with the binary-encoded length, as the new logging

configuration:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>#!/usr/bin/env python

import socket, sys, struct

with open(sys.argv[1], 'rb') as f:

data_to_send = f.read()

HOST = 'localhost'

PORT = 9999

s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)

print('connecting...')

s.connect((HOST, PORT))

print('sending config...')

s.send(struct.pack('>L', len(data_to_send)))

s.send(data_to_send)

s.close()

print('complete')

</pre></div>

</div>

<h2>Dealing with handlers that block<a class="headerlink" href="#dealing-with-handlers-that-block" title="本標題的永久連結">¶</a></h2>

Sometimes you have to get your logging handlers to do their work without

blocking the thread you’re logging from. This is common in Web applications,

though of course it also occurs in other scenarios.

A common culprit which demonstrates sluggish behaviour is the

<a class="reference internal" href="../library/logging.handlers.html#logging.handlers.SMTPHandler" title="logging.handlers.SMTPHandler"><code class="xref py py-class docutils literal notranslate">SMTPHandler</code></a>: sending emails can take a long time, for a

number of reasons outside the developer’s control (for example, a poorly

performing mail or network infrastructure). But almost any network-based

handler can block: Even a <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.SocketHandler" title="logging.handlers.SocketHandler"><code class="xref py py-class docutils literal notranslate">SocketHandler</code></a> operation may do a

DNS query under the hood which is too slow (and this query can be deep in the

socket library code, below the Python layer, and outside your control).

One solution is to use a two-part approach. For the first part, attach only a

<a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueHandler" title="logging.handlers.QueueHandler"><code class="xref py py-class docutils literal notranslate">QueueHandler</code></a> to those loggers which are accessed from

performance-critical threads. They simply write to their queue, which can be

sized to a large enough capacity or initialized with no upper bound to their

size. The write to the queue will typically be accepted quickly, though you

will probably need to catch the <a class="reference internal" href="../library/queue.html#queue.Full" title="queue.Full"><code class="xref py py-exc docutils literal notranslate">queue.Full</code></a> exception as a precaution

in your code. If you are a library developer who has performance-critical

threads in their code, be sure to document this (together with a suggestion to

attach only <code class="docutils literal notranslate">QueueHandlers</code> to your loggers) for the benefit of other

developers who will use your code.

The second part of the solution is <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueListener" title="logging.handlers.QueueListener"><code class="xref py py-class docutils literal notranslate">QueueListener</code></a>, which has been

designed as the counterpart to <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueHandler" title="logging.handlers.QueueHandler"><code class="xref py py-class docutils literal notranslate">QueueHandler</code></a>. A

<a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueListener" title="logging.handlers.QueueListener"><code class="xref py py-class docutils literal notranslate">QueueListener</code></a> is very simple: it’s passed a queue and some handlers,

and it fires up an internal thread which listens to its queue for LogRecords

sent from <code class="docutils literal notranslate">QueueHandlers</code> (or any other source of <code class="docutils literal notranslate">LogRecords</code>, for that

matter). The <code class="docutils literal notranslate">LogRecords</code> are removed from the queue and passed to the

handlers for processing.

The advantage of having a separate <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueListener" title="logging.handlers.QueueListener"><code class="xref py py-class docutils literal notranslate">QueueListener</code></a> class is that you

can use the same instance to service multiple <code class="docutils literal notranslate">QueueHandlers</code>. This is more

resource-friendly than, say, having threaded versions of the existing handler

classes, which would eat up one thread per handler for no particular benefit.

An example of using these two classes follows (imports omitted):

<div class="highlight-python3 notranslate"><div class="highlight"><pre>que = queue.Queue(-1) # no limit on size

queue_handler = QueueHandler(que)

handler = logging.StreamHandler()

listener = QueueListener(que, handler)

root = logging.getLogger()

root.addHandler(queue_handler)

formatter = logging.Formatter('%(threadName)s: %(message)s')

handler.setFormatter(formatter)

listener.start()

# The log output will display the thread which generated

# the event (the main thread) rather than the internal

# thread which monitors the internal queue. This is what

# you want to happen.

root.warning('Look out!')

listener.stop()

</pre></div>

</div>

which, when run, will produce:

<div class="highlight-none notranslate"><div class="highlight"><pre>MainThread: Look out!

</pre></div>

</div>

3.5 版更變: Prior to Python 3.5, the <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueListener" title="logging.handlers.QueueListener"><code class="xref py py-class docutils literal notranslate">QueueListener</code></a> always passed every message

received from the queue to every handler it was initialized with. (This was

because it was assumed that level filtering was all done on the other side,

where the queue is filled.) From 3.5 onwards, this behaviour can be changed

by passing a keyword argument <code class="docutils literal notranslate">respect_handler_level=True</code> to the

listener’s constructor. When this is done, the listener compares the level

of each message with the handler’s level, and only passes a message to a

handler if it’s appropriate to do so.

</div>

<h2>Sending and receiving logging events across a network<a class="headerlink" href="#sending-and-receiving-logging-events-across-a-network" title="本標題的永久連結">¶</a></h2>

Let’s say you want to send logging events across a network, and handle them at

the receiving end. A simple way of doing this is attaching a

<a class="reference internal" href="../library/logging.handlers.html#logging.handlers.SocketHandler" title="logging.handlers.SocketHandler"><code class="xref py py-class docutils literal notranslate">SocketHandler</code></a> instance to the root logger at the sending end:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging, logging.handlers

rootLogger = logging.getLogger('')

rootLogger.setLevel(logging.DEBUG)

socketHandler = logging.handlers.SocketHandler('localhost',

logging.handlers.DEFAULT_TCP_LOGGING_PORT)

# don't bother with a formatter, since a socket handler sends the event as

# an unformatted pickle

rootLogger.addHandler(socketHandler)

# Now, we can log to the root logger, or any other logger. First the root...

logging.info('Jackdaws love my big sphinx of quartz.')

# Now, define a couple of other loggers which might represent areas in your

# application:

logger1.debug('Quick zephyrs blow, vexing daft Jim.')

logger1.info('How quickly daft jumping zebras vex.')

logger2.error('The five boxing wizards jump quickly.')

</pre></div>

</div>

At the receiving end, you can set up a receiver using the <a class="reference internal" href="../library/socketserver.html#module-socketserver" title="socketserver: A framework for network servers."><code class="xref py py-mod docutils literal notranslate">socketserver</code></a>

module. Here is a basic working example:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import pickle

import logging

import logging.handlers

import socketserver

import struct

class LogRecordStreamHandler(socketserver.StreamRequestHandler):

"""Handler for a streaming logging request.

This basically logs the record using whatever logging policy is

configured locally.

"""

def handle(self):

"""

Handle multiple requests - each expected to be a 4-byte length,

followed by the LogRecord in pickle format. Logs the record

according to whatever policy is configured locally.

"""

while True:

chunk = self.connection.recv(4)

if len(chunk) < 4:

break

slen = struct.unpack('>L', chunk)[0]

while len(chunk) < slen:

chunk = chunk + self.connection.recv(slen - len(chunk))

obj = self.unPickle(chunk)

record = logging.makeLogRecord(obj)

self.handleLogRecord(record)

def unPickle(self, data):

return pickle.loads(data)

def handleLogRecord(self, record):

# if a name is specified, we use the named logger rather than the one

# implied by the record.

if self.server.logname is not None:

name = self.server.logname

else:

name = record.name

# N.B. EVERY record gets logged. This is because Logger.handle

# is normally called AFTER logger-level filtering. If you want

# to do filtering, do it at the client end to save wasting

# cycles and network bandwidth!

logger.handle(record)

class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):

"""

Simple TCP socket-based logging receiver suitable for testing.

"""

allow_reuse_address = True

def __init__(self, host='localhost',

port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,

handler=LogRecordStreamHandler):

socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)

self.abort = 0

self.timeout = 1

self.logname = None

def serve_until_stopped(self):

import select

abort = 0

while not abort:

rd, wr, ex = select.select([self.socket.fileno()],

[], [],

self.timeout)

if rd:

self.handle_request()

abort = self.abort

def main():

logging.basicConfig(

format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')

tcpserver = LogRecordSocketReceiver()

print('About to start TCP server...')

tcpserver.serve_until_stopped()

if __name__ == '__main__':

main()

</pre></div>

</div>

First run the server, and then the client. On the client side, nothing is

printed on the console; on the server side, you should see something like:

<div class="highlight-none notranslate"><div class="highlight"><pre>About to start TCP server...

59 root INFO Jackdaws love my big sphinx of quartz.

59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.

69 myapp.area1 INFO How quickly daft jumping zebras vex.

69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.

69 myapp.area2 ERROR The five boxing wizards jump quickly.

</pre></div>

</div>

Note that there are some security issues with pickle in some scenarios. If

these affect you, you can use an alternative serialization scheme by overriding

the <code class="xref py py-meth docutils literal notranslate">makePickle()</code> method and implementing your

alternative there, as well as adapting the above script to use your alternative

serialization.

</div>

<h2>Adding contextual information to your logging output<a class="headerlink" href="#adding-contextual-information-to-your-logging-output" title="本標題的永久連結">¶</a></h2>

Sometimes you want logging output to contain contextual information in

addition to the parameters passed to the logging call. For example, in a

networked application, it may be desirable to log client-specific information

in the log (e.g. remote client’s username, or IP address). Although you could

use the extra parameter to achieve this, it’s not always convenient to pass

the information in this way. While it might be tempting to create

<code class="xref py py-class docutils literal notranslate">Logger</code> instances on a per-connection basis, this is not a good idea

because these instances are not garbage collected. While this is not a problem

in practice, when the number of <code class="xref py py-class docutils literal notranslate">Logger</code> instances is dependent on the

level of granularity you want to use in logging an application, it could

be hard to manage if the number of <code class="xref py py-class docutils literal notranslate">Logger</code> instances becomes

effectively unbounded.

<h3>Using LoggerAdapters to impart contextual information<a class="headerlink" href="#using-loggeradapters-to-impart-contextual-information" title="本標題的永久連結">¶</a></h3>

An easy way in which you can pass contextual information to be output along

with logging event information is to use the <code class="xref py py-class docutils literal notranslate">LoggerAdapter</code> class.

This class is designed to look like a <code class="xref py py-class docutils literal notranslate">Logger</code>, so that you can call

<code class="xref py py-meth docutils literal notranslate">debug()</code>, <code class="xref py py-meth docutils literal notranslate">info()</code>, <code class="xref py py-meth docutils literal notranslate">warning()</code>, <code class="xref py py-meth docutils literal notranslate">error()</code>,

<code class="xref py py-meth docutils literal notranslate">exception()</code>, <code class="xref py py-meth docutils literal notranslate">critical()</code> and <code class="xref py py-meth docutils literal notranslate">log()</code>. These methods have the

same signatures as their counterparts in <code class="xref py py-class docutils literal notranslate">Logger</code>, so you can use the

two types of instances interchangeably.

When you create an instance of <code class="xref py py-class docutils literal notranslate">LoggerAdapter</code>, you pass it a

<code class="xref py py-class docutils literal notranslate">Logger</code> instance and a dict-like object which contains your contextual

information. When you call one of the logging methods on an instance of

<code class="xref py py-class docutils literal notranslate">LoggerAdapter</code>, it delegates the call to the underlying instance of

<code class="xref py py-class docutils literal notranslate">Logger</code> passed to its constructor, and arranges to pass the contextual

information in the delegated call. Here’s a snippet from the code of

<code class="xref py py-class docutils literal notranslate">LoggerAdapter</code>:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>def debug(self, msg, *args, **kwargs):

"""

Delegate a debug call to the underlying logger, after adding

contextual information from this adapter instance.

"""

msg, kwargs = self.process(msg, kwargs)

self.logger.debug(msg, *args, **kwargs)

</pre></div>

</div>

The <code class="xref py py-meth docutils literal notranslate">process()</code> method of <code class="xref py py-class docutils literal notranslate">LoggerAdapter</code> is where the

contextual information is added to the logging output. It’s passed the message

and keyword arguments of the logging call, and it passes back (potentially)

modified versions of these to use in the call to the underlying logger. The

default implementation of this method leaves the message alone, but inserts

an 『extra』 key in the keyword argument whose value is the dict-like object

passed to the constructor. Of course, if you had passed an 『extra』 keyword

argument in the call to the adapter, it will be silently overwritten.

The advantage of using 『extra』 is that the values in the dict-like object are

merged into the <code class="xref py py-class docutils literal notranslate">LogRecord</code> instance’s __dict__, allowing you to use

customized strings with your <code class="xref py py-class docutils literal notranslate">Formatter</code> instances which know about

the keys of the dict-like object. If you need a different method, e.g. if you

want to prepend or append the contextual information to the message string,

you just need to subclass <code class="xref py py-class docutils literal notranslate">LoggerAdapter</code> and override

<code class="xref py py-meth docutils literal notranslate">process()</code> to do what you need. Here is a simple example:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>class CustomAdapter(logging.LoggerAdapter):

"""

This example adapter expects the passed in dict-like object to have a

'connid' key, whose value in brackets is prepended to the log message.

"""

def process(self, msg, kwargs):

return '[%s] %s' % (self.extra['connid'], msg), kwargs

</pre></div>

</div>

which you can use like this:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>logger = logging.getLogger(__name__)

adapter = CustomAdapter(logger, {'connid': some_conn_id})

</pre></div>

</div>

Then any events that you log to the adapter will have the value of

<code class="docutils literal notranslate">some_conn_id</code> prepended to the log messages.

<h4>Using objects other than dicts to pass contextual information<a class="headerlink" href="#using-objects-other-than-dicts-to-pass-contextual-information" title="本標題的永久連結">¶</a></h4>

You don’t need to pass an actual dict to a <code class="xref py py-class docutils literal notranslate">LoggerAdapter</code> - you could

pass an instance of a class which implements <code class="docutils literal notranslate">__getitem__</code> and <code class="docutils literal notranslate">__iter__</code> so

that it looks like a dict to logging. This would be useful if you want to

generate values dynamically (whereas the values in a dict would be constant).

</div>

<h3>Using Filters to impart contextual information<a class="headerlink" href="#using-filters-to-impart-contextual-information" title="本標題的永久連結">¶</a></h3>

You can also add contextual information to log output using a user-defined

<code class="xref py py-class docutils literal notranslate">Filter</code>. <code class="docutils literal notranslate">Filter</code> instances are allowed to modify the <code class="docutils literal notranslate">LogRecords</code>

passed to them, including adding additional attributes which can then be output

using a suitable format string, or if needed a custom <code class="xref py py-class docutils literal notranslate">Formatter</code>.

For example in a web application, the request being processed (or at least,

the interesting parts of it) can be stored in a threadlocal

(<a class="reference internal" href="../library/threading.html#threading.local" title="threading.local"><code class="xref py py-class docutils literal notranslate">threading.local</code></a>) variable, and then accessed from a <code class="docutils literal notranslate">Filter</code> to

add, say, information from the request - say, the remote IP address and remote

user’s username - to the <code class="docutils literal notranslate">LogRecord</code>, using the attribute names 『ip』 and

『user』 as in the <code class="docutils literal notranslate">LoggerAdapter</code> example above. In that case, the same format

string can be used to get similar output to that shown above. Here’s an example

script:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

from random import choice

class ContextFilter(logging.Filter):

"""

This is a filter which injects contextual information into the log.

Rather than use actual contextual information, we just use random

data in this demo.

"""

USERS = ['jim', 'fred', 'sheila']

IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

def filter(self, record):

record.ip = choice(ContextFilter.IPS)

record.user = choice(ContextFilter.USERS)

return True

if __name__ == '__main__':

levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)

format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')

a1 = logging.getLogger('a.b.c')

a2 = logging.getLogger('d.e.f')

f = ContextFilter()

a1.addFilter(f)

a2.addFilter(f)

a1.debug('A debug message')

a1.info('An info message with %s', 'some parameters')

for x in range(10):

lvl = choice(levels)

lvlname = logging.getLevelName(lvl)

a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

</pre></div>

</div>

which, when run, produces something like:

<div class="highlight-none notranslate"><div class="highlight"><pre>2010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message

2010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters

2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters

2010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters

2010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters

2010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters

2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters

2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters

2010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters

2010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters

2010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters

2010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters

</pre></div>

</div>

<h2>Logging to a single file from multiple processes<a class="headerlink" href="#logging-to-a-single-file-from-multiple-processes" title="本標題的永久連結">¶</a></h2>

Although logging is thread-safe, and logging to a single file from multiple

threads in a single process is supported, logging to a single file from

multiple processes is not supported, because there is no standard way to

serialize access to a single file across multiple processes in Python. If you

need to log to a single file from multiple processes, one way of doing this is

to have all the processes log to a <code class="xref py py-class docutils literal notranslate">SocketHandler</code>, and have a

separate process which implements a socket server which reads from the socket

and logs to file. (If you prefer, you can dedicate one thread in one of the

existing processes to perform this function.)

<a class="reference internal" href="#network-logging">This section</a> documents this approach in more detail and

includes a working socket receiver which can be used as a starting point for you

to adapt in your own applications.

If you are using a recent version of Python which includes the

<a class="reference internal" href="../library/multiprocessing.html#module-multiprocessing" title="multiprocessing: Process-based parallelism."><code class="xref py py-mod docutils literal notranslate">multiprocessing</code></a> module, you could write your own handler which uses the

<a class="reference internal" href="../library/multiprocessing.html#multiprocessing.Lock" title="multiprocessing.Lock"><code class="xref py py-class docutils literal notranslate">Lock</code></a> class from this module to serialize access to the

file from your processes. The existing <code class="xref py py-class docutils literal notranslate">FileHandler</code> and subclasses do

not make use of <a class="reference internal" href="../library/multiprocessing.html#module-multiprocessing" title="multiprocessing: Process-based parallelism."><code class="xref py py-mod docutils literal notranslate">multiprocessing</code></a> at present, though they may do so in the

future. Note that at present, the <a class="reference internal" href="../library/multiprocessing.html#module-multiprocessing" title="multiprocessing: Process-based parallelism."><code class="xref py py-mod docutils literal notranslate">multiprocessing</code></a> module does not provide

working lock functionality on all platforms (see

<a class="reference external" href="https://bugs.python.org/issue3770">https://bugs.python.org/issue3770</a>).

Alternatively, you can use a <code class="docutils literal notranslate">Queue</code> and a <a class="reference internal" href="../library/logging.handlers.html#logging.handlers.QueueHandler" title="logging.handlers.QueueHandler"><code class="xref py py-class docutils literal notranslate">QueueHandler</code></a> to send

all logging events to one of the processes in your multi-process application.

The following example script demonstrates how you can do this; in the example

a separate listener process listens for events sent by other processes and logs

them according to its own logging configuration. Although the example only

demonstrates one way of doing it (for example, you may want to use a listener

thread rather than a separate listener process – the implementation would be

analogous) it does allow for completely different logging configurations for

the listener and the other processes in your application, and can be used as

the basis for code meeting your own specific requirements:

<div class="highlight-python3 notranslate"><div class="highlight"><pre># You'll need these imports in your own code

import logging

import logging.handlers

import multiprocessing

# Next two import lines for this demo only

from random import choice, random

import time

#

# Because you'll want to define the logging configurations for listener and workers, the

# listener and worker process functions take a configurer parameter which is a callable

# for configuring logging for that process. These functions are also passed the queue,

# which they use for communication.

#

# In practice, you can configure the listener however you want, but note that in this

# simple example, the listener does not apply level or filter logic to received records.

# In practice, you would probably want to do this logic in the worker processes, to avoid

# sending events which would be filtered out between processes.

#

# The size of the rotated files is made small so you can see the results easily.

def listener_configurer():

root = logging.getLogger()

h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)

f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')

h.setFormatter(f)

root.addHandler(h)

# This is the listener process top-level loop: wait for logging events

# (LogRecords)on the queue and handle them, quit when you get a None for a

# LogRecord.

def listener_process(queue, configurer):

configurer()

while True:

try:

record = queue.get()

if record is None: # We send this as a sentinel to tell the listener to quit.

break

logger = logging.getLogger(record.name)

logger.handle(record) # No level or filter logic applied - just do it!

except Exception:

import sys, traceback

print('Whoops! Problem:', file=sys.stderr)

traceback.print_exc(file=sys.stderr)

# Arrays used for random selections in this demo

LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,

logging.ERROR, logging.CRITICAL]

LOGGERS = ['a.b.c', 'd.e.f']

MESSAGES = [

'Random message #1',

'Random message #2',

'Random message #3',

]

# The worker configuration is done at the start of the worker process run.

# Note that on Windows you can't rely on fork semantics, so each process

# will run the logging configuration code when it starts.

def worker_configurer(queue):

h = logging.handlers.QueueHandler(queue) # Just the one handler needed

root = logging.getLogger()

root.addHandler(h)

# send all messages, for demo; no other level or filter logic applied.

root.setLevel(logging.DEBUG)

# This is the worker process top-level loop, which just logs ten events with

# random intervening delays before terminating.

# The print messages are just so you know it's doing something!

def worker_process(queue, configurer):

configurer(queue)

name = multiprocessing.current_process().name

print('Worker started: %s' % name)

for i in range(10):

time.sleep(random())

logger = logging.getLogger(choice(LOGGERS))

level = choice(LEVELS)

message = choice(MESSAGES)

logger.log(level, message)

print('Worker finished: %s' % name)

# Here's where the demo gets orchestrated. Create the queue, create and start

# the listener, create ten workers and start them, wait for them to finish,

# then send a None to the queue to tell the listener to finish.

def main():

queue = multiprocessing.Queue(-1)

listener = multiprocessing.Process(target=listener_process,

args=(queue, listener_configurer))

listener.start()

workers = []

for i in range(10):

worker = multiprocessing.Process(target=worker_process,

args=(queue, worker_configurer))

workers.append(worker)

worker.start()

for w in workers:

w.join()

queue.put_nowait(None)

listener.join()

if __name__ == '__main__':

main()

</pre></div>

</div>

A variant of the above script keeps the logging in the main process, in a

separate thread:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import logging

import logging.config

import logging.handlers

from multiprocessing import Process, Queue

import random

import threading

import time

def logger_thread(q):

while True:

record = q.get()

if record is None:

break

logger = logging.getLogger(record.name)

logger.handle(record)

def worker_process(q):

qh = logging.handlers.QueueHandler(q)

root = logging.getLogger()

root.addHandler(qh)

levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,

logging.CRITICAL]

loggers = ['foo', 'foo.bar', 'foo.bar.baz',

'spam', 'spam.ham', 'spam.ham.eggs']

for i in range(100):

lvl = random.choice(levels)

logger = logging.getLogger(random.choice(loggers))

logger.log(lvl, 'Message no. %d', i)

if __name__ == '__main__':

q = Queue()

d = {

'version': 1,

'formatters': {

'detailed': {

'class': 'logging.Formatter',

'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'

}

},

'handlers': {

'console': {

'class': 'logging.StreamHandler',

'level': 'INFO',

},

'file': {

'class': 'logging.FileHandler',

'filename': 'mplog.log',

'mode': 'w',

'formatter': 'detailed',

},

'foofile': {

'class': 'logging.FileHandler',

'filename': 'mplog-foo.log',

'mode': 'w',

'formatter': 'detailed',

},

'errors': {

'class': 'logging.FileHandler',

'filename': 'mplog-errors.log',

'mode': 'w',

'level': 'ERROR',

'formatter': 'detailed',

},

'loggers': {

'foo': {

'handlers': ['foofile']

}

},

'root': {

'level': 'DEBUG',

'handlers': ['console', 'file', 'errors']

},

}

workers = []

for i in range(5):

wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))

workers.append(wp)

wp.start()

logging.config.dictConfig(d)

lp = threading.Thread(target=logger_thread, args=(q,))

lp.start()

# At this point, the main process could do some useful work of its own

# Once it's done that, it can wait for the workers to terminate...

for wp in workers:

wp.join()

# And now tell the logging thread to finish up, too

q.put(None)

lp.join()

</pre></div>

</div>

This variant shows how you can e.g. apply configuration for particular loggers

- e.g. the <code class="docutils literal notranslate">foo</code> logger has a special handler which stores all events in the

<code class="docutils literal notranslate">foo</code> subsystem in a file <code class="docutils literal notranslate">mplog-foo.log</code>. This will be used by the logging

machinery in the main process (even though the logging events are generated in

the worker processes) to direct the messages to the appropriate destinations.

</div>

<h2>Using file rotation<a class="headerlink" href="#using-file-rotation" title="本標題的永久連結">¶</a></h2>

Sometimes you want to let a log file grow to a certain size, then open a new

file and log to that. You may want to keep a certain number of these files, and

when that many files have been created, rotate the files so that the number of

files and the size of the files both remain bounded. For this usage pattern, the

logging package provides a <code class="xref py py-class docutils literal notranslate">RotatingFileHandler</code>:

<div class="highlight-python3 notranslate"><div class="highlight"><pre>import glob

import logging

import logging.handlers

LOG_FILENAME = 'logging_rotatingfile_example.out'

# Set up a specific logger with our desired output level

my_logger = logging.getLogger('MyLogger')

my_logger.setLevel(logging.DEBUG)

# Add the log message handler to the logger

handler = logging.handlers.RotatingFileHandler(

LOG_FILENAME, maxBytes=20, backupCount=5)

View remainder of file in raw view

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

FilesExpand file tree

logging-cookbook.html

Latest commit

History

logging-cookbook.html

File metadata and controls